ActiveMQ Topic messages are getting stuck, resent in bulk after glitch

8/26/2020

Environment:

  • ActiveMQ deployed on kubernetes
  • Producer Java Application using openwire
  • Subscribers Python and C client using MQTT

Problem Statement:

  • Producer is sending message after every seconds on Topic and subscriber receiving it accordingly.

  • But sometime once or thrice a day subscriber stop receiving messages for around 4 to 8 seconds then client receive all missing messages within 1 second in bulk.

  • I have enabled debug logs in ActiveMQ but couldn't find any exception/error or warn

Following are client side logs

2020-08-26 07:13:18,852 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
2020-08-26 07:13:19,765 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
2020-08-26 07:13:20,829 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
2020-08-26 07:13:21,784 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
**Here its 5 seconds gap**
2020-08-26 07:13:26,831 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
2020-08-26 07:13:28,745 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
2020-08-26 07:13:29,905 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
2020-08-26 07:13:30,917 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
2020-08-26 07:13:31,484 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
**Three seconds Gap**
2020-08-26 07:13:34,221 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
2020-08-26 07:13:34,881 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
2020-08-26 07:13:37,450 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
2020-08-26 07:13:38,078 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
**Below Can be seen all missing messages received within 1 seconds**
2020-08-26 07:13:40,391 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
2020-08-26 07:13:40,422 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
2020-08-26 07:13:40,423 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
2020-08-26 07:13:40,423 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
2020-08-26 07:13:40,423 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
2020-08-26 07:13:40,423 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
2020-08-26 07:13:40,423 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
2020-08-26 07:13:40,456 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
2020-08-26 07:13:40,456 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
2020-08-26 07:13:40,962 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
2020-08-26 07:13:43,400 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
2020-08-26 07:13:43,475 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
2020-08-26 07:13:44,431 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
2020-08-26 07:13:45,139 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
2020-08-26 07:13:46,074 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'
2020-08-26 07:13:46,787 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'App/status'

Although there is no loss of messages but my application need update within seconds and strange is this happen twice or thrice in 24 hours and random time.

Update1: After doing lot of optimizations and refactoring i finally found root cause

Publisher to Broker Tracs: enter image description here

Publisher suppose to send Frequency status after every 12 millisec but from 13:28:08.132 till 13:28:08.174 it didn't send status and then send all previous missing in one message.

Broker to client logs In below logs we can see clients received status at 175th, 176th, 176th, 177th, 181ist milliseconds. Client was sensitive about it and expect message after every 12 millisec rather than all in one shot

2020-09-27 13:28:08,120 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'PKGCTRL/1/status/frequency', ...  (49 bytes)
2020-09-27 13:28:08,134 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'PKGCTRL/1/status/frequency', ...  (49 bytes)
2020-09-27 13:28:08,175 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'PKGCTRL/1/status/frequency', ...  (49 bytes)
2020-09-27 13:28:08,176 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'PKGCTRL/1/status/frequency', ...  (49 bytes)
2020-09-27 13:28:08,176 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'PKGCTRL/1/status/frequency', ...  (49 bytes)
2020-09-27 13:28:08,177 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'PKGCTRL/1/status/frequency', ...  (49 bytes)
2020-09-27 13:28:08,181 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'PKGCTRL/1/status/frequency', ...  (49 bytes)
2020-09-27 13:28:08,188 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'PKGCTRL/1/status/frequency', ...  (49 bytes)
2020-09-27 13:28:08,200 - DEBUG - Received PUBLISH (d0, q0, r0, m0), 'PKGCTRL/1/status/frequency', ...  (49 bytes)
-- ImranRazaKhan
activemq
amq
kubernetes

0 Answers