search

spring-projects / spring-amqp

Spring AMQP - support for Spring programming model with AMQP, especially but not limited to RabbitMQ
https://spring.io/projects/spring-amqp
Apache License 2.0
809 stars 625 forks source link

rabbitmq listeners are not consuming after connection reset #823

Closed zvikai closed 6 years ago

zvikai commented 6 years ago

We have 2 listeners (java processes inside docker on separated machines) for a rabbit queue(on cloudamqp) that were reading from a queue, and then for some reason stopped reading. According to our logs, on September 30th 2018, 11:28:37.848 (UTC) our application experienced a connection reset:

  September 30th 2018, 11:28:37.848 impl.ForgivingExceptionHandler (ForgivingExceptionHandler.java:120) - An unexpected connection driver error occurred (Exception message: Connection reset)
September 30th 2018, 11:28:37.849 connection.CachingConnectionFactory$DefaultChannelCloseLogger (CachingConnectionFactory.java:1278) - Channel shutdown: connection error
September 30th 2018, 11:28:37.849 connection.CachingConnectionFactory$DefaultChannelCloseLogger (CachingConnectionFactory.java:1278) - Channel shutdown: connection error
September 30th 2018, 11:28:39.401 connection.AbstractConnectionFactory (AbstractConnectionFactory.java:360) - Created new connection: connectionFactory#623d41c5:2/SimpleConnection@1beb3736 [delegate=amqp://xxxx@54.86.215.255:5672/prod, localPort= 57360]  

It seems that since the connection was reset and restored, but we are not getting any new messages from rabbit since then, although there are many messages there. In RabbitMQ Manager I can see the queue size is getting larger but there are no consumers. On thread dump I can see the AMQP thread is running. On netstat I can see connection to cloudamqp is established.   We are running a java application with: openjdk version "1.8.0_151"
org.springframework.boot:spring-boot-starter-amqp:2.0.4.RELEASE   Any help on how to continue investigating.
We don’t want to restart the dockers until it is investigated.

Thanks

garyrussell commented 6 years ago

Please show the thread dump and logs.

zvikai commented 6 years ago

repeating log:

listener.BlockingQueueConsumer (BlockingQueueConsumer.java:484) - Retrieving delivery for Consumer@47629063: tags=[{amq.ctag-w2cwGtZZ1oP_T5WNzfVS5A=segment.router}], channel=Cached Rabbit Channel: AMQChannel(amqp://zgwcvcgk@34.229.170.9:5672/prod,1), conn: Proxy@6a5fad0a Shared Rabbit Connection: SimpleConnection@1e8f91a [delegate=amqp://xxxxxx@34.229.170.9:5672/prod, localPort= 56426], acknowledgeMode=NONE local queue size=0

thread dump:

2018-10-03 18:50:06
Full thread dump OpenJDK 64-Bit Server VM (25.151-b12 mixed mode):

"Attach Listener" #43946 daemon prio=9 os_prio=0 tid=0x000055f0a1dfe000 nid=0x2da9 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"pool-2-thread-13" #43936 prio=5 os_prio=0 tid=0x000055f09de91000 nid=0x2cdd waiting on condition [0x00007f389e2c2000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000f1e070e8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"AMQP Connection 34.229.170.9:5672" #43935 prio=5 os_prio=0 tid=0x000055f0a0472000 nid=0x2cdc runnable [0x00007f389f6ce000]
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
        at java.net.SocketInputStream.read(SocketInputStream.java:171)
        at java.net.SocketInputStream.read(SocketInputStream.java:141)
        at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
        - locked <0x00000000f1e06c30> (a java.io.BufferedInputStream)
        at java.io.DataInputStream.readUnsignedByte(DataInputStream.java:288)
        at com.rabbitmq.client.impl.Frame.readFrom(Frame.java:91)
        at com.rabbitmq.client.impl.SocketFrameHandler.readFrame(SocketFrameHandler.java:164)
        - locked <0x00000000f1e06c10> (a java.io.DataInputStream)
        at com.rabbitmq.client.impl.AMQConnection$MainLoop.run(AMQConnection.java:571)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"Scheduler-675100200" #47 prio=5 os_prio=0 tid=0x000055f0a1824000 nid=0x40 waiting on condition [0x00007f389e9c3000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000f1b830b8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"DestroyJavaVM" #36 prio=5 os_prio=0 tid=0x000055f0a0553800 nid=0x12 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"SimpleAsyncTaskExecutor-1" #31 prio=5 os_prio=0 tid=0x000055f09fc8b000 nid=0x32 waiting on condition [0x00007f389f7cf000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000f1bb5220> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        at java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:467)
        at org.springframework.amqp.rabbit.listener.BlockingQueueConsumer.nextMessage(BlockingQueueConsumer.java:490)
        at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.doReceiveAndExecute(SimpleMessageListenerContainer.java:1249)
        at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.receiveAndExecute(SimpleMessageListenerContainer.java:1224)
        at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.access$1600(SimpleMessageListenerContainer.java:102)
        at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer$AsyncMessageProcessingConsumer.run(SimpleMessageListenerContainer.java:1470)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"spring.cloud.inetutils" #30 daemon prio=5 os_prio=0 tid=0x000055f09f934800 nid=0x31 waiting on condition [0x00007f389fad0000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000f1741610> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"AsyncReporter(org.springframework.cloud.sleuth.zipkin2.sender.RestTemplateSender@7c857e8f)" #29 daemon prio=5 os_prio=0 tid=0x000055f09feec000 nid=0x30 waiting on condition [0x00007f38a0158000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000f1915678> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        at zipkin2.reporter.ByteBoundedQueue.drainTo(ByteBoundedQueue.java:83)
        at zipkin2.reporter.AsyncReporter$BoundedAsyncReporter.flush(AsyncReporter.java:238)
        at zipkin2.reporter.AsyncReporter$Builder.lambda$build$0(AsyncReporter.java:178)
        at zipkin2.reporter.AsyncReporter$Builder$$Lambda$1.run(Unknown Source)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"java-sdk-http-connection-reaper" #28 daemon prio=5 os_prio=0 tid=0x000055f0a12c2000 nid=0x2f waiting on condition [0x00007f389fdd1000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
        at java.lang.Thread.sleep(Native Method)
        at com.amazonaws.http.IdleConnectionReaper.run(IdleConnectionReaper.java:181)

   Locked ownable synchronizers:
        - None

"Scheduler-1305596603" #26 prio=5 os_prio=0 tid=0x000055f0a18b8800 nid=0x2e waiting on condition [0x00007f38a0914000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000f10bcbb8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"qtp663741480-24" #24 prio=5 os_prio=0 tid=0x000055f09fd62000 nid=0x2d waiting on condition [0x00007f38a0a15000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000f0efa2b8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:392)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.idleJobPoll(QueuedThreadPool.java:571)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.access$800(QueuedThreadPool.java:50)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:634)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"qtp663741480-23" #23 prio=5 os_prio=0 tid=0x000055f09fd5f800 nid=0x2c waiting on condition [0x00007f38a0b16000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000f0efa2b8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:392)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.idleJobPoll(QueuedThreadPool.java:571)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.access$800(QueuedThreadPool.java:50)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:634)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"qtp663741480-22" #22 prio=5 os_prio=0 tid=0x000055f09fd5d800 nid=0x2b waiting on condition [0x00007f38a0c17000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000f0efa2b8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:392)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.idleJobPoll(QueuedThreadPool.java:571)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.access$800(QueuedThreadPool.java:50)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:634)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"qtp663741480-21" #21 prio=5 os_prio=0 tid=0x000055f09e6c1800 nid=0x2a waiting on condition [0x00007f38a0fad000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000f1c33fe8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.reservedWait(ReservedThreadExecutor.java:193)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:225)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:679)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:597)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"qtp663741480-20" #20 prio=5 os_prio=0 tid=0x000055f0a09dc000 nid=0x29 waiting on condition [0x00007f38a10ae000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000f1c4a758> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.reservedWait(ReservedThreadExecutor.java:193)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:225)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:679)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:597)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"qtp663741480-19" #19 prio=5 os_prio=0 tid=0x000055f0a2019800 nid=0x28 waiting on condition [0x00007f38a13fc000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000f1c38aa0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.reservedWait(ReservedThreadExecutor.java:193)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:225)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:679)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:597)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"qtp663741480-18-acceptor-0@5181107b-ServerConnector@4fee14b{HTTP/1.1,[http/1.1]}{0.0.0.0:8080}" #18 prio=3 os_prio=0 tid=0x000055f0a2018800 nid=0x27 runnable [0x00007f38a14fd000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method)
        at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:422)
        at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:250)
        - locked <0x00000000f1b82608> (a java.lang.Object)
        at org.eclipse.jetty.server.ServerConnector.accept(ServerConnector.java:379)
        at org.eclipse.jetty.server.AbstractConnector$Acceptor.run(AbstractConnector.java:643)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:679)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:597)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"qtp663741480-17" #17 prio=5 os_prio=0 tid=0x000055f0a201c800 nid=0x26 runnable [0x00007f38a2644000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
        at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
        at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
        - locked <0x00000000f1b81c08> (a sun.nio.ch.Util$3)
        - locked <0x00000000f1b82160> (a java.util.Collections$UnmodifiableSet)
        - locked <0x00000000f1b82018> (a sun.nio.ch.EPollSelectorImpl)
        at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
        at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
        at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.select(ManagedSelector.java:346)
        at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:299)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:179)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:140)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:243)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:679)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:597)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"Spring-Cloud-Vault-2" #15 daemon prio=5 os_prio=0 tid=0x000055f0a123a000 nid=0x24 waiting on condition [0x00007f38a2e43000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000f07c55f0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1088)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"Spring-Cloud-Vault-1" #14 daemon prio=5 os_prio=0 tid=0x000055f0a1238800 nid=0x23 waiting on condition [0x00007f38a2f44000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000f07c55f0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"Service Thread" #8 daemon prio=9 os_prio=0 tid=0x000055f09dd05000 nid=0x1e runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"C1 CompilerThread2" #7 daemon prio=9 os_prio=0 tid=0x000055f09dd01000 nid=0x1d waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"C2 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x000055f09dcff000 nid=0x1c waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x000055f09dcfc000 nid=0x1b waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x000055f09dcf9800 nid=0x1a runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x000055f09dccc000 nid=0x19 in Object.wait() [0x00007f38a8848000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
        - locked <0x00000000f0278a30> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

   Locked ownable synchronizers:
        - None

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x000055f09dcc9800 nid=0x18 in Object.wait() [0x00007f38a8949000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at java.lang.Object.wait(Object.java:502)
        at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
        - locked <0x00000000f0167120> (a java.lang.ref.Reference$Lock)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

   Locked ownable synchronizers:
        - None

"VM Thread" os_prio=0 tid=0x000055f09dcbf000 nid=0x17 runnable 

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x000055f09db8f800 nid=0x13 runnable 

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x000055f09db91000 nid=0x14 runnable 

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x000055f09db93000 nid=0x15 runnable 

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x000055f09db94800 nid=0x16 runnable 

"VM Periodic Task Thread" os_prio=0 tid=0x000055f09dd9b800 nid=0x1f waiting on condition 

JNI global references: 400
artembilan commented 6 years ago

The Retrieving delivery for Consumer means that you definitely consume message from the queue. Or the problem is not related to what you have just shared or you share logs and thread dump in the non-relevant state of your application.

I don't see anything obvious unless you enable native RabbitMQ Cleint recovery via:

    /**
     * Set to true to enable amqp-client automatic recovery. Note: Spring AMQP
     * implements its own connection recovery and this is generally not needed.
     * @param automaticRecoveryEnabled true to enable.
     * @since 1.7.1
     */
    public void setAutomaticRecoveryEnabled(boolean automaticRecoveryEnabled) {
garyrussell commented 6 years ago

@artembilan That trace message is just for polling the internal queue; it doesn't mean we have actually received any messages.

In RabbitMQ Manager I can see the queue size is getting larger but there are no consumers.

tags=[{amq.ctag-w2cwGtZZ1oP_T5WNzfVS5A=segment.router}]

If you don't see a consumer with this tag on the Admin UI then it means the connection was silently dropped somehow which shouldn't be possible, unless you have disabled heartbeats.

slevinson commented 6 years ago

Hey,

we don't see any consumers for the queue, but the guys at cloudamqp helped us identify the connection in Admin UI These are the connection details and client properties, seems that heartbeat is enabled. Please let me know if any additional info could help.

Details Node rabbit@ Client-provided name connectionFactory#623d41c5:2 Username Protocol AMQP 0-9-1 Connected at 2018-09-30 14:28:39 Authentication PLAIN State running Heartbeat 60s Frame max 131072 bytes Channel limit 0 channels

Client properties connection_name connectionFactory#623d41c5:2 product RabbitMQ copyright Copyright (c) 2007-2016 Pivotal Software, Inc. capabilities
exchange_exchange_bindings: true connection.blocked: true authentication_failure_close: true basic.nack: true publisher_confirms: true consumer_cancel_notify: true information Licensed under the MPL. See http://www.rabbitmq.com/ version 4.0.3 platform Java

garyrussell commented 6 years ago

We need to see the logs at the time the connection failure.

slevinson commented 6 years ago

Here are the logs, unfortunately we had it on INFO level, and there are mostly application logs. You can see the connection error log at 11:28:37.848 download link

slevinson commented 6 years ago

after restarting the service, we saw the same behaviour again. here are logs with debug level. connection reset at 2018-10-04 08:54:02.201 download link

garyrussell commented 6 years ago

In the second log, I see messages continue to be received after the connection reset.

DEBUG | 2018-10-04 08:54:06.157 | [SimpleAsyncTaskExecutor-1] |  |  | listener.BlockingQueueConsumer (BlockingQueueConsumer.java:484) - Retrieving delivery for Consumer@5183131d: tags=[{amq.ctag-e4PckB8PDr8bKh9pnM2DRA=segment.router}], channel=Cached Rabbit Channel: AMQChannel(amqp://xxxxxxxx@34.229.170.9:5672/prod,1), conn: Proxy@60cae36 Shared Rabbit Connection: SimpleConnection@1c6eb78d [delegate=amqp://xxxxxxxx@34.229.170.9:5672/prod, localPort= 35534], acknowledgeMode=NONE local queue size=1
DEBUG | 2018-10-04 08:54:06.157 | [SimpleAsyncTaskExecutor-1] |  |  | listener.BlockingQueueConsumer (BlockingQueueConsumer.java:454) - Received message: (Body:'[B@1aa3fbfa(byte[285])' MessageProperties [headers={breadcrumbId=ID-240a0d3530bc-1538225822584-0-45903, Content-Type=application/json, Segment-Type=AUDIO}, timestamp=null, messageId=null, userId=null, receivedUserId=null, appId=null, clusterId=null, type=null, correlationId=null, correlationIdString=null, replyTo=null, contentType=null, contentEncoding=null, contentLength=0, deliveryMode=null, receivedDeliveryMode=null, expiration=null, priority=null, redelivered=false, receivedExchange=segment.exchange, receivedRoutingKey=, receivedDelay=null, deliveryTag=11, messageCount=0, consumerTag=amq.ctag-e4PckB8PDr8bKh9pnM2DRA, consumerQueue=segment.router])
DEBUG | 2018-10-04 08:54:06.157 | [pool-2-thread-4] |  |  | listener.BlockingQueueConsumer$InternalConsumer (BlockingQueueConsumer.java:865) - Storing delivery for Consumer@5183131d: tags=[{amq.ctag-e4PckB8PDr8bKh9pnM2DRA=segment.router}], channel=Cached Rabbit Channel: AMQChannel(amqp://xxxxxxxx@34.229.170.9:5672/prod,1), conn: Proxy@60cae36 Shared Rabbit Connection: SimpleConnection@1c6eb78d [delegate=amqp://xxxxxxxx@34.229.170.9:5672/prod, localPort= 35534], acknowledgeMode=NONE local queue size=1

The connection from port 35534 doesn't appear to have been broken; it was opened at 08:53:16.979.

The connection that broke at 08:54:02.201 appears to be a different connection (health indicator?).

In the first log, it is rather strange that there are no error logs from the listener container (or BlockingQueueConsumer).

However, the SimpleAsyncTaskExecutor-2 thread stopped logging at 11:29:05.671.

That thread does not appear in your thread dump above; and SimpleAsyncTaskExecutor-1 in your thread dump does not appear in the log, so these two artifacts don't appear to reflect the same environment.

slevinson commented 6 years ago

Thanks for your response, and sorry for the confusion, those are indeed two individual environments, both had the same behaviour at about the same time. Here is the log that corresponds to SimpleAsyncTaskExecutor-1 connection reset at 2018-09-30 11:25:57.396 download link

slevinson commented 6 years ago

It is indeed weird that the listener was still handling messages, I figured it was just emptying the local queue.

The answer that we got from cloudamqp was that the connection was reset due to a timeout. At the same time the consumers were removed from the UI, and after the connection was reset, the consumers never came back.

garyrussell commented 6 years ago

Very odd; in both cases, I see the connection reset but no errors in the containers. I do see 9 messsages processed after the failure - presumably you have a prefetch (maybe 10?).

So it simply appears that the container is not informed about the connection loss.

In both cases, however, the new connection is created on threads named qtp1418129042-20 and qtp663741480-17.

The normal behavior is

2018-10-04 13:30:33.923 ERROR 98685 --- [ 127.0.0.1:5672] o.s.a.r.c.CachingConnectionFactory       : Channel shutdown: connection error; protocol method: #method<connection.close>(reply-code=320, reply-text=CONNECTION_FORCED - broker forced connection closure with reason 'shutdown', class-id=0, method-id=0)
2018-10-04 13:30:33.925  WARN 98685 --- [ 127.0.0.1:5672] c.r.c.impl.ForgivingExceptionHandler     : An unexpected connection driver error occured (Exception message: Connection reset)
2018-10-04 13:30:34.516  INFO 98685 --- [cTaskExecutor-1] o.s.a.r.l.SimpleMessageListenerContainer : Restarting Consumer@2371aaca: tags=[{amq.ctag-pHi82CA8JHilDvCpjRV-Uw=spring.gen-ILh4GFNDRtS232ZJcrjs9g}], channel=Cached Rabbit Channel: AMQChannel(amqp://guest@127.0.0.1:5672/,1), conn: Proxy@63e6d632 Shared Rabbit Connection: SimpleConnection@47918f0b [delegate=amqp://guest@127.0.0.1:5672/, localPort= 63102], acknowledgeMode=AUTO local queue size=0
2018-10-04 13:30:34.518  INFO 98685 --- [cTaskExecutor-2] o.s.a.r.c.CachingConnectionFactory       : Attempting to connect to: [localhost:5672]
2018-10-04 13:30:39.559  INFO 98685 --- [cTaskExecutor-3] o.s.a.r.c.CachingConnectionFactory       : Created new connection: rabbitConnectionFactory#545b995e:3/SimpleConnection@39729070 [delegate=amqp://guest@127.0.0.1:5672/, localPort= 63123]

i.e. the container detects the closed connection and reestablishes it.

Whereas in your case, we see

WARN  | 2018-09-30 11:28:37.848 | [AMQP Connection 54.86.215.255:5672] |  |  | impl.ForgivingExceptionHandler (ForgivingExceptionHandler.java:120) - An unexpected connection driver error occured (Exception message: Connection reset)
ERROR | 2018-09-30 11:28:37.849 | [AMQP Connection 54.86.215.255:5672] |  |  | connection.CachingConnectionFactory$DefaultChannelCloseLogger (CachingConnectionFactory.java:1278) - Channel shutdown: connection error
ERROR | 2018-09-30 11:28:37.849 | [AMQP Connection 54.86.215.255:5672] |  |  | connection.CachingConnectionFactory$DefaultChannelCloseLogger (CachingConnectionFactory.java:1278) - Channel shutdown: connection error
INFO  | 2018-09-30 11:28:39.401 | [qtp1418129042-20] | ef04644f26045703 | ef04644f26045703 | connection.AbstractConnectionFactory (AbstractConnectionFactory.java:360) - Created new connection: connectionFactory#623d41c5:2/SimpleConnection@1beb3736 [delegate=amqp://******@54.86.215.255:5672/prod, localPort= 57360]

I see you are using a version that's over a year old; the latest 1.7.x version is 1.7.10; I don't recall any changes in this area, but can you upgrade?

What are these qtp1418129042-20 threads?

garyrussell commented 6 years ago

I just tested with 17.4 and I still see the (current) behavior - even with a prefetch, processing stops immediately and the consumer is restarted.

I have no idea what's happening. The sequence is this...

When the channel is shut down, the amqp-client calls the consumer's handleShutdownSignal(), in there we set the BlockingQueueConmsumers shutdown field with the exception. Then, each time we look for a message (even if prefetched) we check that field (and throw it). This is the signal to the container that it needs to go into recovery mode and restart the consumers.

I have no idea why, but the fact you still process prefetched records after the closure means the amqp-client never called the consumer s handleShutdownSignal().

This code has been in place since early 2011 and I have never heard of such a problem before.

slevinson commented 6 years ago

we are actually using org.springframework.boot:spring-boot-starter-amqp:2.0.4.RELEASE isn't it using spring-ampq of the same version?

in other services we are using org.springframework.boot:spring-boot-starter-amqp:1.5.9.RELEASE and haven't experienced this problem, of course it is also different code.

garyrussell commented 6 years ago

Well, in the second log you sent, I see

WARN  | 2018-10-04 08:54:02.201 | [qtp1136705850-20] | 99e76713ff0c4270 | 99e76713ff0c4270 | health.AbstractHealthIndicator (AbstractHealthIndicator.java:46) - Health check failed
org.springframework.amqp.AmqpIOException: java.net.SocketException: Connection reset
    at org.springframework.amqp.rabbit.support.RabbitExceptionTranslator.convertRabbitAccessException(RabbitExceptionTranslator.java:71) ~[spring-rabbit-1.7.4.RELEASE.jar:?]
    at org.springframework.amqp.rabbit.connection.SimpleConnection.createChannel(SimpleConnection.java:63) ~[spring-rabbit-1.7.4.RELEASE.jar:?]

Hence my thought that this was what you are using.

Boot 2.0.4 will use spring-rabbit 2.0.5.RELEASE (unless overridden). Boot 2.0.5 uses 2.0.6 - the release cycles are not aligned.

As I said, this code has been present for over 7 years without any problems being reported.

I am still suspicious about these qtp1418129042-20 threads and what they are doing - is it possible you have 2 connections? Even so, it's still not clear how this could possibly happen if heartbeats are present.

garyrussell commented 6 years ago

Boot 2.0.x is not compatible with 1.7.x so something is not right.

slevinson commented 6 years ago

Oh! that could be it then.... I do see spring-rabbit and spring-amqp 1.7.4 jar files under External Libraries in IntelliJ I guess we made some mess with different versions in our build.gradle file.

I'll see if we can align those and hope it helps, your help is very appreciated! thanks!

garyrussell commented 6 years ago

Well. I meant a Boot 2.0 application won't even start with 1.7.x on the classpath.

slevinson commented 6 years ago

We have references to spring-boot 1.5.9 and spring-boot-starter-amqp 2.0.4 build.gradle (some proprietary removed)

garyrussell commented 6 years ago

Right, but the Boot version is 1.5.9

springBootVersion            : "1.5.9.RELEASE",

so that's ok. BTW, the boot version that brings in 1.7.10 is 1.5.16.

The starter really has no differences between versions (take a look in the jar - just a couple of text files). That said, you should generally use the same versions for all boot artifacts.

slevinson commented 6 years ago

so you don't think the versions mismatch was the issue?

garyrussell commented 6 years ago

No; I do not (but it's always a good idea to stay current rather than using year old software).

Perhaps docker is causing some weirdness but, again, this is the first time I've ever heard or seen a container fail to be notified of a broken connection.

zvikai commented 6 years ago

It was not reproduced again till now. Closing the issue.

gstaykov commented 5 years ago

I get the same error after connection is restored there are no consumers for the queue using @RabbitListener . I need to restart my service to resolve the problem

  1. Spring boot 1.5.7.RELEASE ( org.springframework.amqp:spring-rabbit:jar:1.7.4.RELEASE:compile )
  2. rabbitmq 3.7.14 Erlang 21.3.7
  3. Java 8

Steps to reproduce:

  1. Create listener using @RabbitListener like this:

    @RabbitListener(
bindings = @QueueBinding(
        key = COMMON,
        value = @Queue(value = "some.queue.name",
                   autoDelete = "true"),
        exchange = @Exchange(value = "some.exchange.name",
                                         type = ExchangeTypes.TOPIC,
                                         durable = "true")
    )
)

  2. Restart the rabbitmq server using the following commands:

    rabbitmqctl stop_app
rabbitmqctl reset    # this one delete all config
rabbitmqctl start_app

The exceptions that I get is:

  1. com.rabbitmq.client.impl.ForgivingExceptionHandler
com.rabbitmq.client.impl.ForgivingExceptionHandler
An unexpected connection driver error occured (Exception message: Socket closed)
  1. Health check failed from org.springframework.boot.actuate.health.RabbitHealthIndicator
org.springframework.amqp.AmqpIOException: java.io.IOException
    at org.springframework.amqp.rabbit.support.RabbitExceptionTranslator.convertRabbitAccessException(RabbitExceptionTranslator.java:71)
    at org.springframework.amqp.rabbit.connection.AbstractConnectionFactory.createBareConnection(AbstractConnectionFactory.java:368)
    at org.springframework.amqp.rabbit.connection.CachingConnectionFactory.createConnection(CachingConnectionFactory.java:573)
    at org.springframework.amqp.rabbit.core.RabbitTemplate.doExecute(RabbitTemplate.java:1430)
    at org.springframework.amqp.rabbit.core.RabbitTemplate.execute(RabbitTemplate.java:1411)
    at org.springframework.amqp.rabbit.core.RabbitTemplate.execute(RabbitTemplate.java:1387)
    at org.springframework.boot.actuate.health.RabbitHealthIndicator.getVersion(RabbitHealthIndicator.java:49)
    at org.springframework.boot.actuate.health.RabbitHealthIndicator.doHealthCheck(RabbitHealthIndicator.java:45)
    at org.springframework.boot.actuate.health.AbstractHealthIndicator.health(AbstractHealthIndicator.java:43)
    at org.springframework.boot.actuate.health.CompositeHealthIndicator.health(CompositeHealthIndicator.java:68)
    at org.springframework.boot.actuate.endpoint.HealthEndpoint.invoke(HealthEndpoint.java:85)
    at org.springframework.boot.actuate.endpoint.mvc.HealthMvcEndpoint.getCurrentHealth(HealthMvcEndpoint.java:177)
    at org.springframework.boot.actuate.endpoint.mvc.HealthMvcEndpoint.getHealth(HealthMvcEndpoint.java:166)
    at org.springframework.boot.actuate.endpoint.mvc.HealthMvcEndpoint.invoke(HealthMvcEndpoint.java:143)
    at sun.reflect.GeneratedMethodAccessor291.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)
    at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:133)
    at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:97)
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827)
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738)
    at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)
    at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:967)
    at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:901)
    at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
    at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:861)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:635)
    at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.boot.web.filter.ApplicationContextHeaderFilter.doFilterInternal(ApplicationContextHeaderFilter.java:55)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at com.trader.logger.filter.LoggerFilter.doFilter(LoggerFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.boot.actuate.trace.WebRequestTraceFilter.doFilterInternal(WebRequestTraceFilter.java:110)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:108)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:81)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.boot.actuate.autoconfigure.MetricsFilter.doFilterInternal(MetricsFilter.java:106)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:478)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:80)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
    at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:799)
    at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1457)
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.io.IOException: null
    at com.rabbitmq.client.impl.AMQChannel.wrap(AMQChannel.java:105)
    at com.rabbitmq.client.impl.AMQChannel.wrap(AMQChannel.java:101)
    at com.rabbitmq.client.impl.AMQChannel.exnWrappingRpc(AMQChannel.java:123)
    at com.rabbitmq.client.impl.AMQConnection.start(AMQConnection.java:381)
    at com.rabbitmq.client.ConnectionFactory.newConnection(ConnectionFactory.java:909)
    at com.rabbitmq.client.ConnectionFactory.newConnection(ConnectionFactory.java:859)
    at com.rabbitmq.client.ConnectionFactory.newConnection(ConnectionFactory.java:799)
    at org.springframework.amqp.rabbit.connection.AbstractConnectionFactory.createBareConnection(AbstractConnectionFactory.java:352)
    ... 80 common frames omitted
Caused by: com.rabbitmq.client.ShutdownSignalException: connection error; protocol method: #method<connection.close>(reply-code=530, reply-text=NOT_ALLOWED - access to vhost '/' refused for user 'instrumentory', class-id=10, method-id=40)
    at com.rabbitmq.utility.ValueOrException.getValue(ValueOrException.java:66)
    at com.rabbitmq.utility.BlockingValueOrException.uninterruptibleGetValue(BlockingValueOrException.java:32)
    at com.rabbitmq.client.impl.AMQChannel$BlockingRpcContinuation.getReply(AMQChannel.java:366)
    at com.rabbitmq.client.impl.AMQChannel.privateRpc(AMQChannel.java:229)
    at com.rabbitmq.client.impl.AMQChannel.exnWrappingRpc(AMQChannel.java:117)
    ... 85 common frames omitted
garyrussell commented 5 years ago

Please don't comment on old, closed issues; open a new one if you feel there is a bug.

Caused by: com.rabbitmq.client.ShutdownSignalException: connection error; protocol method: #method(reply-code=530, reply-text=NOT_ALLOWED - access to vhost '/' refused for user 'instrumentory', class-id=10, method-id=40)

Of course; you have reset the configuration - why would you expect this to work?

reset Removes the node from any cluster it belongs to, removes all data from the management database, such as configured users and vhosts, and deletes all persistent messages.

I don't see how restarting the app can fix this.

gstaykov commented 5 years ago

The app must reconnect and re-create the exchange, the queue and the binding between them and everything must be working smoothly when the rabbitmq server is back and working again. But this doesn't happen. Everything is re-created (connection, exchange, queue and biding) successfully but the queue doesn't have consumers

garyrussell commented 5 years ago

But that's not what you show - you show the health check failed because the user was deleted. How can we create queues etc if the user is no longer valid?

gstaykov commented 5 years ago

I said that the app must re-create everything after the rabbitmq server is back and woking properly again. This means that you need to restore the rabbitmq users after the server is up and running again. Obviously this is done because after the restart of the rabbitmq the java app re-creates the queue, the exchange and binding between them without restarting the java app => the connection is also re-created. The only problem is that the queue doesn't have consumers after it was re-created

garyrussell commented 5 years ago

Authentication failures are considered fatal and the container will stop.

2019-05-13 11:56:00.851 ERROR 2528 --- [tContainer#0-46] o.s.a.r.l.SimpleMessageListenerContainer : Consumer received fatal exception on startup

org.springframework.amqp.rabbit.listener.exception.FatalListenerStartupException: Authentication failure
    at org.springframework.amqp.rabbit.listener.BlockingQueueConsumer.start(BlockingQueueConsumer.java:582) ~[spring-rabbit-1.7.13.RELEASE.jar:na]
    at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer$AsyncMessageProcessingConsumer.run(SimpleMessageListenerContainer.java:1504) ~[spring-rabbit-1.7.13.RELEASE.jar:na]
    at java.lang.Thread.run(Thread.java:748) [na:1.8.0_181]
Caused by: org.springframework.amqp.AmqpAuthenticationException: com.rabbitmq.client.AuthenticationFailureException: ACCESS_REFUSED - Login was refused using authentication mechanism PLAIN. For details see the broker logfile.
    at org.springframework.amqp.rabbit.support.RabbitExceptionTranslator.convertRabbitAccessException(RabbitExceptionTranslator.java:65) ~[spring-rabbit-1.7.13.RELEASE.jar:na]
    at org.springframework.amqp.rabbit.connection.AbstractConnectionFactory.createBareConnection(AbstractConnectionFactory.java:407) ~[spring-rabbit-1.7.13.RELEASE.jar:na]
    at org.springframework.amqp.rabbit.connection.CachingConnectionFactory.createConnection(CachingConnectionFactory.java:588) ~[spring-rabbit-1.7.13.RELEASE.jar:na]
    at org.springframework.amqp.rabbit.connection.ConnectionFactoryUtils$1.createConnection(ConnectionFactoryUtils.java:90) ~[spring-rabbit-1.7.13.RELEASE.jar:na]
    at org.springframework.amqp.rabbit.connection.ConnectionFactoryUtils.doGetTransactionalResourceHolder(ConnectionFactoryUtils.java:140) ~[spring-rabbit-1.7.13.RELEASE.jar:na]
    at org.springframework.amqp.rabbit.connection.ConnectionFactoryUtils.getTransactionalResourceHolder(ConnectionFactoryUtils.java:76) ~[spring-rabbit-1.7.13.RELEASE.jar:na]
    at org.springframework.amqp.rabbit.listener.BlockingQueueConsumer.start(BlockingQueueConsumer.java:576) ~[spring-rabbit-1.7.13.RELEASE.jar:na]
    ... 2 common frames omitted
Caused by: com.rabbitmq.client.AuthenticationFailureException: ACCESS_REFUSED - Login was refused using authentication mechanism PLAIN. For details see the broker logfile.
    at com.rabbitmq.client.impl.AMQConnection.start(AMQConnection.java:368) ~[amqp-client-4.8.3.jar:4.8.3]
    at com.rabbitmq.client.ConnectionFactory.newConnection(ConnectionFactory.java:1159) ~[amqp-client-4.8.3.jar:4.8.3]
    at com.rabbitmq.client.ConnectionFactory.newConnection(ConnectionFactory.java:1109) ~[amqp-client-4.8.3.jar:4.8.3]
    at com.rabbitmq.client.ConnectionFactory.newConnection(ConnectionFactory.java:1049) ~[amqp-client-4.8.3.jar:4.8.3]
    at org.springframework.amqp.rabbit.connection.AbstractConnectionFactory.createBareConnection(AbstractConnectionFactory.java:367) ~[spring-rabbit-1.7.13.RELEASE.jar:na]
    ... 7 common frames omitted

There is currently no way to change that behavior.

Why would you perform such a catastrophic operation in production?

You can restart the container programmatically via the RabbitListenerEndpointRegistry (give the @RabbitListener an id and get the container from the registry and start() it).

gstaykov commented 5 years ago

I'm just testing a scenario what will happen if rabbitmq server crashes. I have come in situation where all of our hardware in the datacenter crashes and we need to move the services on another hardware (these machines were running only infrastructure services like db, messaging, proxies etc. backend services were on another hardware working ok). I will try the RabbitListenerEndpointRegistry tomorrow thanks.