You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@activemq.apache.org by John Lilley <jo...@redpointglobal.com.INVALID> on 2023/03/19 21:02:17 UTC
Please help finding lost packet
Greetings!
Our app is heavy on the RPC pattern using the Artemis JMS client API. Our RPC client sends a request to a named service queue, and waits for a reply on a reply-to queue. This mostly works great, but under load, and in the Kubernetes environment, something goes wrong and a message is lost.
I am beginning to suspect that that this is due to using a single reply-to temporary queue for a long lifetime. It is OK to use a temporary queue for a long time? If there is a connection error (like I think we see below), should I be creating a new reply queue?
Apologies in advance because I feel like we keep nibbling around the edge of the same symptoms and never quite getting enough information to completely resolve it. Hopefully this time we’ve logged enough detail and uncovered something new that will open the door to an answer.
We recently logged an issue that seems to come down to:
* There is an error logged at low levels of the AMQ client
* These errors seem to mostly self-recover but not before a 30-second timeout.
* Our RPC client sends a request message to a named service queue
* Our RPC service receives the request and sends a reply message to the (temporary) reply-to queue
* ActiveMQ broker log shows the reply SEND but not the DELIVER
* On examination of the AMQ console, the reply-to queue exists, has one message, but no consumers
On the face of it this seems simple. We must be closing the reply consumer or session. But we see evidence that something else is going wrong at a lower level.
I keep scouring our code for where we might be closing a session or consumer, and I just can’t find anything, because:
* We create Connections statically and never close them
* We use a singleton reply-to queue and MessageListener, and receive all replies through this one consumer
* Our singleton MessageListener creates and owns its Session, Consumer, and Queue, and never closes them
In the log of our RPC client:
2023-03-18T03:02:27.290 [Thread-1 (ActiveMQ-client-global-threads)] client.connectionFailureDetected:293 [] WARN - AMQ212037: Connection failure to dm-activemq-svc/10.0.202.122:61616 has been detected: AMQ219014: Timed out after waiting 30000 ms for response when sending packet 71 [code=CONNECTION_TIMEDOUT]
2023-03-18T03:02:27.294 [Thread-1 (ActiveMQ-client-global-threads)] ClientSessionFactoryImpl.failoverOrReconnect:555 [] DEBUG - Failure captured on connectionID=c8929f70, performing failover or reconnection now ActiveMQConnectionTimedOutException[errorType=CONNECTION_TIMEDOUT message=AMQ219014: Timed out after waiting 30000 ms for response when sending packet 71]
…
2023-03-18T03:02:27.466 [Thread-1901] JmsStaticConnectionPool.onException:78 [] ERROR - Receive error occurred. javax.jms.JMSException: ActiveMQConnectionTimedOutException[errorType=CONNECTION_TIMEDOUT message=AMQ219014: Timed out after waiting 30000 ms for response when sending packet 71]
You can see more detail at: https://drive.google.com/file/d/1-ThbTMQAPAJwNUI4HIlmFKXf-yB9p59E/view?usp=share_link
I’ve got our code set to log a thread stack dump when this happens, so there is a lot of detail there.
The JmsStaticConnectionPool.onException() is our registered exception handler. We don’t try to recover or anything in this method, we just log the error. Should we be doing something here? I’ve never been able to understand under what circumstances we need to actively recover from errors.
Shortly after that, we attempt another RPC call, which receives no reply:
2023-03-18T03:02:28.424 [HpaK8S] JmsRpcClientChannel.prepareCall:81 [] INFO - REQUEST OUT: { "header": {"version":1,"type":"void","id":"om8xv1gdjvsb","api":"hpa_metrics","method":"get_expected_pod_counts","authorization":"***REDACTED***"}, "body":{"message_type":"void"} }
2023-03-18T03:02:28.427 [HpaK8S] AbstractProducerCreditsImpl.checkCredits:182 [] DEBUG - not asking for -1 credits on rpdm.v1.hpa.metrics
2023-03-18T03:02:28.427 [HpaK8S] AbstractProducerCreditsImpl.afterAcquired:90 [] DEBUG - AfterAcquire 679 credits on address rpdm.v1.hpa.metrics
You can see this is received in our service log and a reply is sent:
2023-03-18T03:02:30.292 [Thread-68 (ActiveMQ-client-global-threads)] JmsServerBase.logRequest:107 [] INFO - REQUEST IN: { "header": {"version":1,"type":"void","id":"om8xv1gdjvsb","api":"hpa_metrics","method":"get_expected_pod_counts","authorization":"***REDACTED***","chain":[]}, "body":"***ERROR NO MESSAGE BODY***" }
2023-03-18T03:02:30.292 [Thread-68 (ActiveMQ-client-global-threads)] JmsServerBase.logResponse:114 [om8xv1gdjvsb] INFO - RESPONSE OUT: { "header": {"version":1,"type":"expected_pod_counts_response","id":"om8xv1gdjvsb","http_code":200}, "body":{"counts":[{"message_type":"expected_pod_count_response","pod_type":"project_execution","memory_mb":2048,"jvm_memory_mb":250,"count":1},{"message_type":"expected_pod_count_response","pod_type":"project_execution","memory_mb":6144,"jvm_memory_mb":2000,"count":0},{"message_type":"expected_pod_count_response","pod_type":"project_edit","memory_mb":500,"jvm_memory_mb":500,"count":1},{"message_type":"expected_pod_count_response","pod_type":"automation_edit","memory_mb":500,"jvm_memory_mb":500,"count":0},{"message_type":"expected_pod_count_response","pod_type":"automation_execution","memory_mb":500,"jvm_memory_mb":250,"count":0}],"message_type":"expected_pod_counts_response"} }
In the AMQ broker log the request SEND and DELIVER:
2023-03-17T21:02:28-06:00 2023-03-18 03:02:28,427 INFO [net.redpoint.rpdm.artemis_logger.RpdmArtemisLogger] SEND: { "header": {"version":1,"type":"void","id":"om8xv1gdjvsb","api":"hpa_metrics","method":"get_expected_pod_counts","authorization":"Bwuth0M2TKk1Znm+iD7+Pew2hp4Klq5+eTjGuWEjfn4="}, "body":{"message_type":"void"} }
2023-03-17T21:02:30-06:00 2023-03-18 03:02:30,183 INFO [net.redpoint.rpdm.artemis_logger.RpdmArtemisLogger] DELIVER: { "header": {"version":1,"type":"void","id":"om8xv1gdjvsb","api":"hpa_metrics","method":"get_expected_pod_counts","authorization":"Bwuth0M2TKk1Znm+iD7+Pew2hp4Klq5+eTjGuWEjfn4="}, "body":{"message_type":"void"} }
But the response only SEND, no DELIVER:
2023-03-17T21:02:30-06:00 2023-03-18 03:02:30,305 INFO [net.redpoint.rpdm.artemis_logger.RpdmArtemisLogger] SEND: { "header": {"version":1,"type":"expected_pod_counts_response","id":"om8xv1gdjvsb","http_code":200}, "body":{"counts":[{"message_type":"expected_pod_count_response","pod_type":"project_execution","memory_mb":2048,"jvm_memory_mb":250,"count":1},{"message_type":"expected_pod_count_response","pod_type":"project_execution","memory_mb":6144,"jvm_memory_mb":2000,"count":0},{"message_type":"expected_pod_count_response","pod_type":"project_edit","memory_mb":500,"jvm_memory_mb":500,"count":1},{"message_type":"expected_pod_count_response","pod_type":"automation_edit","memory_mb":500,"jvm_memory_mb":500,"count":0},{"message_type":"expected_pod_count_response","pod_type":"automation_execution","memory_mb":500,"jvm_memory_mb":250,"count":0}],"message_type":"expected_pod_counts_response"} }
This is consistent with the reply-to consumer being closed, but I cannot how or when it is closed. Also in the AMQ console we see the consumer count is zero and there is one message, so it certainly acts like the reply-to consumer was closed.
I should mention that we see a lot of these in our RPC client log, but since there so many I assumed they were harmless:
2023-03-18T03:02:36.094 [Thread-2] ClientSessionImpl.close:1333 [] DEBUG - Calling close on session ClientSessionImpl [name=509b0e84-c539-11ed-911b-86945e7d6721, username=null, closed=false, factory = org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl@50f3a373<ma...@50f3a373>, metaData=()]@d95cd6d
2023-03-18T03:02:36.095 [Thread-2] ClientSessionImpl.doCleanup:2080 [] DEBUG - calling cleanup on ClientSessionImpl [name=509b0e84-c539-11ed-911b-86945e7d6721, username=null, closed=false, factory = org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl@50f3a373<ma...@50f3a373>, metaData=()]@d95cd6d
I looked back 30 seconds in the RPC client log, and didn’t see anything odd, but there is this unusual flurry:
2023-03-18T03:01:57.255 [HpaMetrics-Background] AbstractProducerCreditsImpl.checkCredits:182 [] DEBUG - not asking for -1 credits on activemq.management
2023-03-18T03:01:57.255 [HpaMetrics-Background] AbstractProducerCreditsImpl.afterAcquired:90 [] DEBUG - AfterAcquire 413 credits on address activemq.management
2023-03-18T03:01:57.256 [HpaMetrics-Background] AbstractProducerCreditsImpl.checkCredits:182 [] DEBUG - not asking for -1 credits on activemq.management
2023-03-18T03:01:57.256 [HpaMetrics-Background] AbstractProducerCreditsImpl.afterAcquired:90 [] DEBUG - AfterAcquire 415 credits on address activemq.management
2023-03-18T03:01:57.257 [HpaMetrics-Background] AbstractProducerCreditsImpl.checkCredits:182 [] DEBUG - not asking for -1 credits on activemq.management
2023-03-18T03:01:57.257 [HpaMetrics-Background] AbstractProducerCreditsImpl.afterAcquired:90 [] DEBUG - AfterAcquire 389 credits on address activemq.management
2023-03-18T03:01:57.257 [HpaMetrics-Background] AbstractProducerCreditsImpl.checkCredits:182 [] DEBUG - not asking for -1 credits on activemq.management
2023-03-18T03:01:57.257 [HpaMetrics-Background] AbstractProducerCreditsImpl.afterAcquired:90 [] DEBUG - AfterAcquire 395 credits on address activemq.management
2023-03-18T03:01:57.258 [HpaMetrics-Background] AbstractProducerCreditsImpl.checkCredits:182 [] DEBUG - not asking for -1 credits on activemq.management
2023-03-18T03:01:57.258 [HpaMetrics-Background] AbstractProducerCreditsImpl.afterAcquired:90 [] DEBUG - AfterAcquire 401 credits on address activemq.management
Meanwhile, we have a custom logger installed in the AMQ broker, and everything looks fine until it is not:
[rg] <https://www.redpointglobal.com/>
John Lilley
Data Management Chief Architect, Redpoint Global Inc.
888 Worcester Street, Suite 200 Wellesley, MA 02482
M: +1 7209385761<tel:+1%207209385761> | john.lilley@redpointglobal.com<ma...@redpointglobal.com>
PLEASE NOTE: This e-mail from Redpoint Global Inc. (“Redpoint”) is confidential and is intended solely for the use of the individual(s) to whom it is addressed. If you believe you received this e-mail in error, please notify the sender immediately, delete the e-mail from your computer and do not copy, print or disclose it to anyone else. If you properly received this e-mail as a customer, partner or vendor of Redpoint, you should maintain its contents in confidence subject to the terms and conditions of your agreement(s) with Redpoint.
Re: Please help finding lost packet
Posted by David Bennion <da...@gmx.com>.
Hey John,
So we had a problem recently that we debugged into and the concept of
credits is related to flow control implemented by the broker. We had a
situation where under load and potentially due to something else going
on our side where messages stopped being delivered all together.
And in the debugger we found the credit system was actually preventing
delivery of the messages. But it was too complicated for me to piece
together exactly why. In our situation, the system didn't seem to
recover and deliver messages again without a restart -- or maybe it just
took longer than we were willing to wait. When we turned off the flow
control, the problem completely went away. We do have some logical flow
control on the outside of our use of the broker, so it is not like we're
completely without flow control.
Just where you said stuff kind of hangs and doesn't deliver until it
recovers after 30 seconds and those credit messages are present it
seemed to resonate a bit with what we had seen recently. (I am not deep
enough in technical understanding of all aspects of the broker to know
for sure, so apologies if this is chatter that misdirects your thinking).
Best of luck,
David.
On 3/20/23 9:58 AM, John Lilley wrote:
>
> Hi David,
>
> If by that you mean lines like:
> 2023-03-18T03:01:57.255 [HpaMetrics-Background]
> AbstractProducerCreditsImpl.checkCredits:182
> <ftp://AbstractProducerCreditsImpl.checkCredits/182> [] DEBUG - not
> asking for -1 credits on activemq.management 2023-03-18T03:01:57.255
> [HpaMetrics-Background] AbstractProducerCreditsImpl.afterAcquired:90
> <ftp://AbstractProducerCreditsImpl.afterAcquired/90> [] DEBUG -
> AfterAcquire 413 credits on address activemq.management
>
> I don't get the feeling those actually hurt anything because they
> happen all the time. But I really don't know what they are.
>
> John
>
>
>
> rg <https://www.redpointglobal.com/>
>
>
>
> John Lilley
>
> Data Management Chief Architect, Redpoint Global Inc.
>
> 888 Worcester Street, Suite 200 Wellesley, MA 02482
>
> *M: *+1 7209385761 <tel:+1 7209385761> | john.lilley@redpointglobal.com
>
> -----Original Message-----
> From: David Bennion <da...@gmx.com>
> Sent: Sunday, March 19, 2023 6:09 PM
> To: users@activemq.apache.org
> Cc: Lewis Gass <le...@redpointglobal.com>
> Subject: Re: Please help finding lost packet
>
> *** [Caution] This email is from an external source. Please use
> caution responding, opening attachments or clicking embedded links. ***
>
> Those errors at the end feel awfully similar to an issue that we ran
> into recently.
>
> We resolved by disabling flow control by setting consumerWindowSize
> and producerWindowSize both to -1 as I recall. Our end conclusion was
> that the flow control stuff in the broker was getting confused and
> then declining to deliver messages. This would only happen under heavy
> load.
>
>
>
> PLEASE NOTE: This e-mail from Redpoint Global Inc. (“Redpoint”) is
> confidential and is intended solely for the use of the individual(s)
> to whom it is addressed. If you believe you received this e-mail in
> error, please notify the sender immediately, delete the e-mail from
> your computer and do not copy, print or disclose it to anyone else. If
> you properly received this e-mail as a customer, partner or vendor of
> Redpoint, you should maintain its contents in confidence subject to
> the terms and conditions of your agreement(s) with Redpoint.
RE: Please help finding lost packet
Posted by John Lilley <jo...@redpointglobal.com.INVALID>.
Hi David,
If by that you mean lines like:
2023-03-18T03:01:57.255 [HpaMetrics-Background] AbstractProducerCreditsImpl.checkCredits:182<ftp://AbstractProducerCreditsImpl.checkCredits/182> [] DEBUG - not asking for -1 credits on activemq.management 2023-03-18T03:01:57.255 [HpaMetrics-Background] AbstractProducerCreditsImpl.afterAcquired:90<ftp://AbstractProducerCreditsImpl.afterAcquired/90> [] DEBUG - AfterAcquire 413 credits on address activemq.management
I don't get the feeling those actually hurt anything because they happen all the time. But I really don't know what they are.
John
[rg] <https://www.redpointglobal.com/>
John Lilley
Data Management Chief Architect, Redpoint Global Inc.
888 Worcester Street, Suite 200 Wellesley, MA 02482
M: +1 7209385761<tel:+1%207209385761> | john.lilley@redpointglobal.com<ma...@redpointglobal.com>
-----Original Message-----
From: David Bennion <da...@gmx.com>>
Sent: Sunday, March 19, 2023 6:09 PM
To: users@activemq.apache.org<ma...@activemq.apache.org>
Cc: Lewis Gass <le...@redpointglobal.com>>
Subject: Re: Please help finding lost packet
*** [Caution] This email is from an external source. Please use caution responding, opening attachments or clicking embedded links. ***
Those errors at the end feel awfully similar to an issue that we ran into recently.
We resolved by disabling flow control by setting consumerWindowSize and producerWindowSize both to -1 as I recall. Our end conclusion was that the flow control stuff in the broker was getting confused and then declining to deliver messages. This would only happen under heavy load.
PLEASE NOTE: This e-mail from Redpoint Global Inc. (“Redpoint”) is confidential and is intended solely for the use of the individual(s) to whom it is addressed. If you believe you received this e-mail in error, please notify the sender immediately, delete the e-mail from your computer and do not copy, print or disclose it to anyone else. If you properly received this e-mail as a customer, partner or vendor of Redpoint, you should maintain its contents in confidence subject to the terms and conditions of your agreement(s) with Redpoint.
Re: Please help finding lost packet
Posted by David Bennion <da...@gmx.com>.
Those errors at the end feel awfully similar to an issue that we ran into recently.
We resolved by disabling flow control by setting consumerWindowSize and producerWindowSize both to -1 as I recall. Our end conclusion was that the flow control stuff in the broker was getting confused and then declining to deliver messages. This would only happen under heavy load.
Get BlueMail for Android
On Mar 19, 2023, 3:03 PM, at 3:03 PM, John Lilley <jo...@redpointglobal.com.invalid> wrote:
>Greetings!
>
>Our app is heavy on the RPC pattern using the Artemis JMS client API.
>Our RPC client sends a request to a named service queue, and waits for
>a reply on a reply-to queue. This mostly works great, but under load,
>and in the Kubernetes environment, something goes wrong and a message
>is lost.
>
>I am beginning to suspect that that this is due to using a single
>reply-to temporary queue for a long lifetime. It is OK to use a
>temporary queue for a long time? If there is a connection error (like
>I think we see below), should I be creating a new reply queue?
>
>Apologies in advance because I feel like we keep nibbling around the
>edge of the same symptoms and never quite getting enough information to
>completely resolve it. Hopefully this time we’ve logged enough detail
>and uncovered something new that will open the door to an answer.
>
>We recently logged an issue that seems to come down to:
>
> * There is an error logged at low levels of the AMQ client
>* These errors seem to mostly self-recover but not before a 30-second
>timeout.
> * Our RPC client sends a request message to a named service queue
>* Our RPC service receives the request and sends a reply message to
>the (temporary) reply-to queue
> * ActiveMQ broker log shows the reply SEND but not the DELIVER
>* On examination of the AMQ console, the reply-to queue exists, has
>one message, but no consumers
>
>On the face of it this seems simple. We must be closing the reply
>consumer or session. But we see evidence that something else is going
>wrong at a lower level.
>
>I keep scouring our code for where we might be closing a session or
>consumer, and I just can’t find anything, because:
>
> * We create Connections statically and never close them
>* We use a singleton reply-to queue and MessageListener, and receive
>all replies through this one consumer
>* Our singleton MessageListener creates and owns its Session,
>Consumer, and Queue, and never closes them
>
>In the log of our RPC client:
>2023-03-18T03:02:27.290 [Thread-1 (ActiveMQ-client-global-threads)]
>client.connectionFailureDetected:293 [] WARN - AMQ212037: Connection
>failure to dm-activemq-svc/10.0.202.122:61616 has been detected:
>AMQ219014: Timed out after waiting 30000 ms for response when sending
>packet 71 [code=CONNECTION_TIMEDOUT]
>2023-03-18T03:02:27.294 [Thread-1 (ActiveMQ-client-global-threads)]
>ClientSessionFactoryImpl.failoverOrReconnect:555 [] DEBUG - Failure
>captured on connectionID=c8929f70, performing failover or reconnection
>now ActiveMQConnectionTimedOutException[errorType=CONNECTION_TIMEDOUT
>message=AMQ219014: Timed out after waiting 30000 ms for response when
>sending packet 71]
>…
>2023-03-18T03:02:27.466 [Thread-1901]
>JmsStaticConnectionPool.onException:78 [] ERROR - Receive error
>occurred. javax.jms.JMSException:
>ActiveMQConnectionTimedOutException[errorType=CONNECTION_TIMEDOUT
>message=AMQ219014: Timed out after waiting 30000 ms for response when
>sending packet 71]
>You can see more detail at:
>https://drive.google.com/file/d/1-ThbTMQAPAJwNUI4HIlmFKXf-yB9p59E/view?usp=share_link
>I’ve got our code set to log a thread stack dump when this happens, so
>there is a lot of detail there.
>
>The JmsStaticConnectionPool.onException() is our registered exception
>handler. We don’t try to recover or anything in this method, we just
>log the error. Should we be doing something here? I’ve never been
>able to understand under what circumstances we need to actively recover
>from errors.
>
>Shortly after that, we attempt another RPC call, which receives no
>reply:
>2023-03-18T03:02:28.424 [HpaK8S] JmsRpcClientChannel.prepareCall:81 []
>INFO - REQUEST OUT: { "header":
>{"version":1,"type":"void","id":"om8xv1gdjvsb","api":"hpa_metrics","method":"get_expected_pod_counts","authorization":"***REDACTED***"},
>"body":{"message_type":"void"} }
>2023-03-18T03:02:28.427 [HpaK8S]
>AbstractProducerCreditsImpl.checkCredits:182 [] DEBUG - not asking for
>-1 credits on rpdm.v1.hpa.metrics
>2023-03-18T03:02:28.427 [HpaK8S]
>AbstractProducerCreditsImpl.afterAcquired:90 [] DEBUG - AfterAcquire
>679 credits on address rpdm.v1.hpa.metrics
>
>You can see this is received in our service log and a reply is sent:
>2023-03-18T03:02:30.292 [Thread-68 (ActiveMQ-client-global-threads)]
>JmsServerBase.logRequest:107 [] INFO - REQUEST IN: { "header":
>{"version":1,"type":"void","id":"om8xv1gdjvsb","api":"hpa_metrics","method":"get_expected_pod_counts","authorization":"***REDACTED***","chain":[]},
>"body":"***ERROR NO MESSAGE BODY***" }
>2023-03-18T03:02:30.292 [Thread-68 (ActiveMQ-client-global-threads)]
>JmsServerBase.logResponse:114 [om8xv1gdjvsb] INFO - RESPONSE OUT: {
>"header":
>{"version":1,"type":"expected_pod_counts_response","id":"om8xv1gdjvsb","http_code":200},
>"body":{"counts":[{"message_type":"expected_pod_count_response","pod_type":"project_execution","memory_mb":2048,"jvm_memory_mb":250,"count":1},{"message_type":"expected_pod_count_response","pod_type":"project_execution","memory_mb":6144,"jvm_memory_mb":2000,"count":0},{"message_type":"expected_pod_count_response","pod_type":"project_edit","memory_mb":500,"jvm_memory_mb":500,"count":1},{"message_type":"expected_pod_count_response","pod_type":"automation_edit","memory_mb":500,"jvm_memory_mb":500,"count":0},{"message_type":"expected_pod_count_response","pod_type":"automation_execution","memory_mb":500,"jvm_memory_mb":250,"count":0}],"message_type":"expected_pod_counts_response"}
>}
>
>In the AMQ broker log the request SEND and DELIVER:
>2023-03-17T21:02:28-06:00 2023-03-18 03:02:28,427 INFO
>[net.redpoint.rpdm.artemis_logger.RpdmArtemisLogger] SEND: { "header":
>{"version":1,"type":"void","id":"om8xv1gdjvsb","api":"hpa_metrics","method":"get_expected_pod_counts","authorization":"Bwuth0M2TKk1Znm+iD7+Pew2hp4Klq5+eTjGuWEjfn4="},
>"body":{"message_type":"void"} }
>2023-03-17T21:02:30-06:00 2023-03-18 03:02:30,183 INFO
>[net.redpoint.rpdm.artemis_logger.RpdmArtemisLogger] DELIVER: {
>"header":
>{"version":1,"type":"void","id":"om8xv1gdjvsb","api":"hpa_metrics","method":"get_expected_pod_counts","authorization":"Bwuth0M2TKk1Znm+iD7+Pew2hp4Klq5+eTjGuWEjfn4="},
>"body":{"message_type":"void"} }
>
>But the response only SEND, no DELIVER:
>2023-03-17T21:02:30-06:00 2023-03-18 03:02:30,305 INFO
>[net.redpoint.rpdm.artemis_logger.RpdmArtemisLogger] SEND: { "header":
>{"version":1,"type":"expected_pod_counts_response","id":"om8xv1gdjvsb","http_code":200},
>"body":{"counts":[{"message_type":"expected_pod_count_response","pod_type":"project_execution","memory_mb":2048,"jvm_memory_mb":250,"count":1},{"message_type":"expected_pod_count_response","pod_type":"project_execution","memory_mb":6144,"jvm_memory_mb":2000,"count":0},{"message_type":"expected_pod_count_response","pod_type":"project_edit","memory_mb":500,"jvm_memory_mb":500,"count":1},{"message_type":"expected_pod_count_response","pod_type":"automation_edit","memory_mb":500,"jvm_memory_mb":500,"count":0},{"message_type":"expected_pod_count_response","pod_type":"automation_execution","memory_mb":500,"jvm_memory_mb":250,"count":0}],"message_type":"expected_pod_counts_response"}
>}
>
>This is consistent with the reply-to consumer being closed, but I
>cannot how or when it is closed. Also in the AMQ console we see the
>consumer count is zero and there is one message, so it certainly acts
>like the reply-to consumer was closed.
>
>I should mention that we see a lot of these in our RPC client log, but
>since there so many I assumed they were harmless:
>2023-03-18T03:02:36.094 [Thread-2] ClientSessionImpl.close:1333 []
>DEBUG - Calling close on session ClientSessionImpl
>[name=509b0e84-c539-11ed-911b-86945e7d6721, username=null,
>closed=false, factory =
>org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl@50f3a373<ma...@50f3a373>,
>metaData=()]@d95cd6d
>2023-03-18T03:02:36.095 [Thread-2] ClientSessionImpl.doCleanup:2080 []
>DEBUG - calling cleanup on ClientSessionImpl
>[name=509b0e84-c539-11ed-911b-86945e7d6721, username=null,
>closed=false, factory =
>org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl@50f3a373<ma...@50f3a373>,
>metaData=()]@d95cd6d
>
>I looked back 30 seconds in the RPC client log, and didn’t see anything
>odd, but there is this unusual flurry:
>2023-03-18T03:01:57.255 [HpaMetrics-Background]
>AbstractProducerCreditsImpl.checkCredits:182 [] DEBUG - not asking for
>-1 credits on activemq.management
>2023-03-18T03:01:57.255 [HpaMetrics-Background]
>AbstractProducerCreditsImpl.afterAcquired:90 [] DEBUG - AfterAcquire
>413 credits on address activemq.management
>2023-03-18T03:01:57.256 [HpaMetrics-Background]
>AbstractProducerCreditsImpl.checkCredits:182 [] DEBUG - not asking for
>-1 credits on activemq.management
>2023-03-18T03:01:57.256 [HpaMetrics-Background]
>AbstractProducerCreditsImpl.afterAcquired:90 [] DEBUG - AfterAcquire
>415 credits on address activemq.management
>2023-03-18T03:01:57.257 [HpaMetrics-Background]
>AbstractProducerCreditsImpl.checkCredits:182 [] DEBUG - not asking for
>-1 credits on activemq.management
>2023-03-18T03:01:57.257 [HpaMetrics-Background]
>AbstractProducerCreditsImpl.afterAcquired:90 [] DEBUG - AfterAcquire
>389 credits on address activemq.management
>2023-03-18T03:01:57.257 [HpaMetrics-Background]
>AbstractProducerCreditsImpl.checkCredits:182 [] DEBUG - not asking for
>-1 credits on activemq.management
>2023-03-18T03:01:57.257 [HpaMetrics-Background]
>AbstractProducerCreditsImpl.afterAcquired:90 [] DEBUG - AfterAcquire
>395 credits on address activemq.management
>2023-03-18T03:01:57.258 [HpaMetrics-Background]
>AbstractProducerCreditsImpl.checkCredits:182 [] DEBUG - not asking for
>-1 credits on activemq.management
>2023-03-18T03:01:57.258 [HpaMetrics-Background]
>AbstractProducerCreditsImpl.afterAcquired:90 [] DEBUG - AfterAcquire
>401 credits on address activemq.management
>
>Meanwhile, we have a custom logger installed in the AMQ broker, and
>everything looks fine until it is not:
>
>
>
>[rg] <https://www.redpointglobal.com/>
>
>John Lilley
>
>Data Management Chief Architect, Redpoint Global Inc.
>
>888 Worcester Street, Suite 200 Wellesley, MA 02482
>
>M: +1 7209385761<tel:+1%207209385761> |
>john.lilley@redpointglobal.com<ma...@redpointglobal.com>
>
>PLEASE NOTE: This e-mail from Redpoint Global Inc. (“Redpoint”) is
>confidential and is intended solely for the use of the individual(s) to
>whom it is addressed. If you believe you received this e-mail in error,
>please notify the sender immediately, delete the e-mail from your
>computer and do not copy, print or disclose it to anyone else. If you
>properly received this e-mail as a customer, partner or vendor of
>Redpoint, you should maintain its contents in confidence subject to the
>terms and conditions of your agreement(s) with Redpoint.
>
>
>------------------------------------------------------------------------
>
>Greetings!
>
>
>
>Our app is heavy on the RPC pattern using the Artemis JMS client API.
>Our RPC client sends a request to a named service queue, and waits for
>a reply on a reply-to queue. This mostly works great, but under load,
>and in the Kubernetes environment, something goes wrong and a message
>is lost.
>
>
>
>I am beginning to suspect that that this is due to using a single
>reply-to temporary queue for a long lifetime. It is OK to use a
>temporary queue for a long time? If there is a connection error (like
>I think we see below), should I be creating a new reply queue?
>
>
>
>Apologies in advance because I feel like we keep nibbling around the
>edge of the same symptoms and never quite getting enough information to
>completely resolve it. Hopefully this time we’ve logged enough detail
>and uncovered something new that will open the door to an answer.
>
>
>
>We recently logged an issue that seems to come down to:
>
>There is an error logged at low levels of the AMQ client
>
>These errors seem to mostly self-recover but not before a 30-second
>timeout.
>
>Our RPC client sends a request message to a named service queue
>
>Our RPC service receives the request and sends a reply message to the
>(temporary) reply-to queue
>
>ActiveMQ broker log shows the reply SEND but not the DELIVER
>
>On examination of the AMQ console, the reply-to queue exists, has one
>message, but no consumers
>
>
>
>On the face of it this seems simple. We must be closing the reply
>consumer or session. But we see evidence that something else is going
>wrong at a lower level.
>
>
>
>I keep scouring our code for where we might be closing a session or
>consumer, and I just can’t find anything, because:
>
>We create Connections statically and never close them
>
>We use a singleton reply-to queue and MessageListener, and receive all
>replies through this one consumer
>
>Our singleton MessageListener creates and owns its Session, Consumer,
>and Queue, and never closes them
>
>
>
>In the log of our RPC client:
>
>2023-03-18T03:02:27.290 [Thread-1 (ActiveMQ-client-global-threads)]
>client.connectionFailureDetected:293 [] WARN - AMQ212037: Connection
>failure to dm-activemq-svc/10.0.202.122:61616 has been detected:
>AMQ219014: Timed out after waiting 30000 ms for response when sending
>packet 71 [code=CONNECTION_TIMEDOUT]
>
>2023-03-18T03:02:27.294 [Thread-1 (ActiveMQ-client-global-threads)]
>ClientSessionFactoryImpl.failoverOrReconnect:555 [] DEBUG - Failure
>captured on connectionID=c8929f70, performing failover or reconnection
>now ActiveMQConnectionTimedOutException[errorType=CONNECTION_TIMEDOUT
>message=AMQ219014: Timed out after waiting 30000 ms for response when
>sending packet 71]
>
>…
>
>2023-03-18T03:02:27.466 [Thread-1901]
>JmsStaticConnectionPool.onException:78 [] ERROR - Receive error
>occurred. javax.jms.JMSException:
>ActiveMQConnectionTimedOutException[errorType=CONNECTION_TIMEDOUT
>message=AMQ219014: Timed out after waiting 30000 ms for response when
>sending packet 71]
>
>You can see more detail at:
>https://drive.google.com/file/d/1-ThbTMQAPAJwNUI4HIlmFKXf-yB9p59E/view?usp=share_link
>
>I’ve got our code set to log a thread stack dump when this happens, so
>there is a lot of detail there.
>
>
>
>The JmsStaticConnectionPool.onException() is our registered exception
>handler. We don’t try to recover or anything in this method, we just
>log the error. Should we be doing something here? I’ve never been
>able to understand under what circumstances we need to actively recover
>from errors.
>
>
>
>Shortly after that, we attempt another RPC call, which receives no
>reply:
>
>2023-03-18T03:02:28.424 [HpaK8S] JmsRpcClientChannel.prepareCall:81 []
>INFO - REQUEST OUT: { "header":
>{"version":1,"type":"void","id":"om8xv1gdjvsb","api":"hpa_metrics","method":"get_expected_pod_counts","authorization":"***REDACTED***"},
>"body":{"message_type":"void"} }
>
>2023-03-18T03:02:28.427 [HpaK8S]
>AbstractProducerCreditsImpl.checkCredits:182 [] DEBUG - not asking for
>-1 credits on rpdm.v1.hpa.metrics
>
>2023-03-18T03:02:28.427 [HpaK8S]
>AbstractProducerCreditsImpl.afterAcquired:90 [] DEBUG - AfterAcquire
>679 credits on address rpdm.v1.hpa.metrics
>
>
>
>You can see this is received in our service log and a reply is sent:
>
>2023-03-18T03:02:30.292 [Thread-68 (ActiveMQ-client-global-threads)]
>JmsServerBase.logRequest:107 [] INFO - REQUEST IN: { "header":
>{"version":1,"type":"void","id":"om8xv1gdjvsb","api":"hpa_metrics","method":"get_expected_pod_counts","authorization":"***REDACTED***","chain":[]},
>"body":"***ERROR NO MESSAGE BODY***" }
>
>2023-03-18T03:02:30.292 [Thread-68 (ActiveMQ-client-global-threads)]
>JmsServerBase.logResponse:114 [om8xv1gdjvsb] INFO - RESPONSE OUT: {
>"header":
>{"version":1,"type":"expected_pod_counts_response","id":"om8xv1gdjvsb","http_code":200},
>"body":{"counts":[{"message_type":"expected_pod_count_response","pod_type":"project_execution","memory_mb":2048,"jvm_memory_mb":250,"count":1},{"message_type":"expected_pod_count_response","pod_type":"project_execution","memory_mb":6144,"jvm_memory_mb":2000,"count":0},{"message_type":"expected_pod_count_response","pod_type":"project_edit","memory_mb":500,"jvm_memory_mb":500,"count":1},{"message_type":"expected_pod_count_response","pod_type":"automation_edit","memory_mb":500,"jvm_memory_mb":500,"count":0},{"message_type":"expected_pod_count_response","pod_type":"automation_execution","memory_mb":500,"jvm_memory_mb":250,"count":0}],"message_type":"expected_pod_counts_response"}
>}
>
>
>
>In the AMQ broker log the request SEND and DELIVER:
>
>2023-03-17T21:02:28-06:00 2023-03-18 03:02:28,427 INFO
>[net.redpoint.rpdm.artemis_logger.RpdmArtemisLogger] SEND: { "header":
>{"version":1,"type":"void","id":"om8xv1gdjvsb","api":"hpa_metrics","method":"get_expected_pod_counts","authorization":"Bwuth0M2TKk1Znm+iD7+Pew2hp4Klq5+eTjGuWEjfn4="},
>"body":{"message_type":"void"} }
>
>2023-03-17T21:02:30-06:00 2023-03-18 03:02:30,183 INFO
>[net.redpoint.rpdm.artemis_logger.RpdmArtemisLogger] DELIVER: {
>"header":
>{"version":1,"type":"void","id":"om8xv1gdjvsb","api":"hpa_metrics","method":"get_expected_pod_counts","authorization":"Bwuth0M2TKk1Znm+iD7+Pew2hp4Klq5+eTjGuWEjfn4="},
>"body":{"message_type":"void"} }
>
>
>
>But the response only SEND, no DELIVER:
>
>2023-03-17T21:02:30-06:00 2023-03-18 03:02:30,305 INFO
>[net.redpoint.rpdm.artemis_logger.RpdmArtemisLogger] SEND: { "header":
>{"version":1,"type":"expected_pod_counts_response","id":"om8xv1gdjvsb","http_code":200},
>"body":{"counts":[{"message_type":"expected_pod_count_response","pod_type":"project_execution","memory_mb":2048,"jvm_memory_mb":250,"count":1},{"message_type":"expected_pod_count_response","pod_type":"project_execution","memory_mb":6144,"jvm_memory_mb":2000,"count":0},{"message_type":"expected_pod_count_response","pod_type":"project_edit","memory_mb":500,"jvm_memory_mb":500,"count":1},{"message_type":"expected_pod_count_response","pod_type":"automation_edit","memory_mb":500,"jvm_memory_mb":500,"count":0},{"message_type":"expected_pod_count_response","pod_type":"automation_execution","memory_mb":500,"jvm_memory_mb":250,"count":0}],"message_type":"expected_pod_counts_response"}
>}
>
>
>
>This is consistent with the reply-to consumer being closed, but I
>cannot how or when it is closed. Also in the AMQ console we see the
>consumer count is zero and there is one message, so it certainly acts
>like the reply-to consumer was closed.
>
>
>
>I should mention that we see a lot of these in our RPC client log, but
>since there so many I assumed they were harmless:
>
>2023-03-18T03:02:36.094 [Thread-2] ClientSessionImpl.close:1333 []
>DEBUG - Calling close on session ClientSessionImpl
>[name=509b0e84-c539-11ed-911b-86945e7d6721, username=null,
>closed=false, factory =
>org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl@50f3a373,
>metaData=()]@d95cd6d
>
>2023-03-18T03:02:36.095 [Thread-2] ClientSessionImpl.doCleanup:2080 []
>DEBUG - calling cleanup on ClientSessionImpl
>[name=509b0e84-c539-11ed-911b-86945e7d6721, username=null,
>closed=false, factory =
>org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl@50f3a373,
>metaData=()]@d95cd6d
>
>
>
>I looked back 30 seconds in the RPC client log, and didn’t see anything
>odd, but there is this unusual flurry:
>
>2023-03-18T03:01:57.255 [HpaMetrics-Background]
>AbstractProducerCreditsImpl.checkCredits:182 [] DEBUG - not asking for
>-1 credits on activemq.management
>
>2023-03-18T03:01:57.255 [HpaMetrics-Background]
>AbstractProducerCreditsImpl.afterAcquired:90 [] DEBUG - AfterAcquire
>413 credits on address activemq.management
>
>2023-03-18T03:01:57.256 [HpaMetrics-Background]
>AbstractProducerCreditsImpl.checkCredits:182 [] DEBUG - not asking for
>-1 credits on activemq.management
>
>2023-03-18T03:01:57.256 [HpaMetrics-Background]
>AbstractProducerCreditsImpl.afterAcquired:90 [] DEBUG - AfterAcquire
>415 credits on address activemq.management
>
>2023-03-18T03:01:57.257 [HpaMetrics-Background]
>AbstractProducerCreditsImpl.checkCredits:182 [] DEBUG - not asking for
>-1 credits on activemq.management
>
>2023-03-18T03:01:57.257 [HpaMetrics-Background]
>AbstractProducerCreditsImpl.afterAcquired:90 [] DEBUG - AfterAcquire
>389 credits on address activemq.management
>
>2023-03-18T03:01:57.257 [HpaMetrics-Background]
>AbstractProducerCreditsImpl.checkCredits:182 [] DEBUG - not asking for
>-1 credits on activemq.management
>
>2023-03-18T03:01:57.257 [HpaMetrics-Background]
>AbstractProducerCreditsImpl.afterAcquired:90 [] DEBUG - AfterAcquire
>395 credits on address activemq.management
>
>2023-03-18T03:01:57.258 [HpaMetrics-Background]
>AbstractProducerCreditsImpl.checkCredits:182 [] DEBUG - not asking for
>-1 credits on activemq.management
>
>2023-03-18T03:01:57.258 [HpaMetrics-Background]
>AbstractProducerCreditsImpl.afterAcquired:90 [] DEBUG - AfterAcquire
>401 credits on address activemq.management
>
>
>
>Meanwhile, we have a custom logger installed in the AMQ broker, and
>everything looks fine until it is not:
>
>
>
>
>
>
>John Lilley
>
>Data Management Chief Architect, Redpoint Global Inc.
>
>888 Worcester Street, Suite 200 Wellesley, MA 02482
>
>M: +1 7209385761 | john.lilley@redpointglobal.com
>
>
>PLEASE NOTE: This e-mail from Redpoint Global Inc. (“Redpoint”) is
>confidential and is intended solely for the use of the individual(s) to
>whom it is addressed. If you believe you received this e-mail in error,
>please notify the sender immediately, delete the e-mail from your
>computer and do not copy, print or disclose it to anyone else. If you
>properly received this e-mail as a customer, partner or vendor of
>Redpoint, you should maintain its contents in confidence subject to the
>terms and conditions of your agreement(s) with Redpoint.
Re: Please help finding lost packet
Posted by Justin Bertram <jb...@apache.org>.
I think the fact that you're getting AMQ219014 explains most, if not all,
of the issues. The "packet 71" that is timing out here is the packet used
to send a message from the core client to the broker. As far as I can tell
this is your "lost" message although it's not really lost since you got a
clear exception indicating that sending the message failed. This message
will not be resent automatically for the same basic reasons I explained on
your other thread [1].
Justin
[1] https://lists.apache.org/thread/6q7zoczljslbr26v845fycz4lfdgs3nk
On Sun, Mar 19, 2023 at 4:03 PM John Lilley
<jo...@redpointglobal.com.invalid> wrote:
> Greetings!
>
>
>
> Our app is heavy on the RPC pattern using the Artemis JMS client API. Our
> RPC client sends a request to a named service queue, and waits for a reply
> on a reply-to queue. This mostly works great, but under load, and in the
> Kubernetes environment, something goes wrong and a message is lost.
>
>
>
> I am beginning to suspect that that this is due to using a single reply-to
> temporary queue for a long lifetime. It is OK to use a temporary queue for
> a long time? If there is a connection error (like I think we see below),
> should I be creating a new reply queue?
>
>
>
> Apologies in advance because I feel like we keep nibbling around the edge
> of the same symptoms and never quite getting enough information to
> completely resolve it. Hopefully this time we’ve logged enough detail and
> uncovered something new that will open the door to an answer.
>
>
>
> We recently logged an issue that seems to come down to:
>
> - There is an error logged at low levels of the AMQ client
> - These errors seem to mostly self-recover but not before a 30-second
> timeout.
> - Our RPC client sends a request message to a named service queue
> - Our RPC service receives the request and sends a reply message to
> the (temporary) reply-to queue
> - ActiveMQ broker log shows the reply SEND but not the DELIVER
> - On examination of the AMQ console, the reply-to queue exists, has
> one message, but no consumers
>
>
>
> On the face of it this seems simple. We must be closing the reply
> consumer or session. But we see evidence that something else is going
> wrong at a lower level.
>
>
>
> I keep scouring our code for where we might be closing a session or
> consumer, and I just can’t find anything, because:
>
> - We create Connections statically and never close them
> - We use a singleton reply-to queue and MessageListener, and receive
> all replies through this one consumer
> - Our singleton MessageListener creates and owns its Session,
> Consumer, and Queue, and never closes them
>
>
>
> In the log of our RPC client:
>
> 2023-03-18T03:02:27.290 [Thread-1 (ActiveMQ-client-global-threads)]
> client.connectionFailureDetected:293 [] WARN - AMQ212037: Connection
> failure to dm-activemq-svc/10.0.202.122:61616 has been detected:
> AMQ219014: Timed out after waiting 30000 ms for response when sending
> packet 71 [code=CONNECTION_TIMEDOUT]
>
> 2023-03-18T03:02:27.294 [Thread-1 (ActiveMQ-client-global-threads)]
> ClientSessionFactoryImpl.failoverOrReconnect:555 [] DEBUG - Failure
> captured on connectionID=c8929f70, performing failover or reconnection now
> ActiveMQConnectionTimedOutException[errorType=CONNECTION_TIMEDOUT
> message=AMQ219014: Timed out after waiting 30000 ms for response when
> sending packet 71]
>
> …
>
> 2023-03-18T03:02:27.466 [Thread-1901]
> JmsStaticConnectionPool.onException:78 [] ERROR - Receive error occurred.
> javax.jms.JMSException:
> ActiveMQConnectionTimedOutException[errorType=CONNECTION_TIMEDOUT
> message=AMQ219014: Timed out after waiting 30000 ms for response when
> sending packet 71]
>
> You can see more detail at:
> https://drive.google.com/file/d/1-ThbTMQAPAJwNUI4HIlmFKXf-yB9p59E/view?usp=share_link
>
> I’ve got our code set to log a thread stack dump when this happens, so
> there is a lot of detail there.
>
>
>
> The JmsStaticConnectionPool.onException() is our registered exception
> handler. We don’t try to recover or anything in this method, we just log
> the error. *Should we be doing something here? *I’ve never been able to
> understand under what circumstances we need to actively recover from errors.
>
>
>
> Shortly after that, we attempt another RPC call, which receives no reply:
>
> 2023-03-18T03:02:28.424 [HpaK8S] JmsRpcClientChannel.prepareCall:81 []
> INFO - REQUEST OUT: { "header":
> {"version":1,"type":"void","id":"om8xv1gdjvsb","api":"hpa_metrics","method":"get_expected_pod_counts","authorization":"***REDACTED***"},
> "body":{"message_type":"void"} }
>
> 2023-03-18T03:02:28.427 [HpaK8S]
> AbstractProducerCreditsImpl.checkCredits:182 [] DEBUG - not asking for -1
> credits on rpdm.v1.hpa.metrics
>
> 2023-03-18T03:02:28.427 [HpaK8S]
> AbstractProducerCreditsImpl.afterAcquired:90 [] DEBUG - AfterAcquire 679
> credits on address rpdm.v1.hpa.metrics
>
>
>
> You can see this is received in our service log and a reply is sent:
>
> 2023-03-18T03:02:30.292 [Thread-68 (ActiveMQ-client-global-threads)]
> JmsServerBase.logRequest:107 [] INFO - REQUEST IN: { "header":
> {"version":1,"type":"void","id":"om8xv1gdjvsb","api":"hpa_metrics","method":"get_expected_pod_counts","authorization":"***REDACTED***","chain":[]},
> "body":"***ERROR NO MESSAGE BODY***" }
>
> 2023-03-18T03:02:30.292 [Thread-68 (ActiveMQ-client-global-threads)]
> JmsServerBase.logResponse:114 [om8xv1gdjvsb] INFO - RESPONSE OUT: {
> "header":
> {"version":1,"type":"expected_pod_counts_response","id":"om8xv1gdjvsb","http_code":200},
> "body":{"counts":[{"message_type":"expected_pod_count_response","pod_type":"project_execution","memory_mb":2048,"jvm_memory_mb":250,"count":1},{"message_type":"expected_pod_count_response","pod_type":"project_execution","memory_mb":6144,"jvm_memory_mb":2000,"count":0},{"message_type":"expected_pod_count_response","pod_type":"project_edit","memory_mb":500,"jvm_memory_mb":500,"count":1},{"message_type":"expected_pod_count_response","pod_type":"automation_edit","memory_mb":500,"jvm_memory_mb":500,"count":0},{"message_type":"expected_pod_count_response","pod_type":"automation_execution","memory_mb":500,"jvm_memory_mb":250,"count":0}],"message_type":"expected_pod_counts_response"}
> }
>
>
>
> In the AMQ broker log the request SEND and DELIVER:
>
> 2023-03-17T21:02:28-06:00 2023-03-18 03:02:28,427 INFO
> [net.redpoint.rpdm.artemis_logger.RpdmArtemisLogger] SEND: { "header":
> {"version":1,"type":"void","id":"om8xv1gdjvsb","api":"hpa_metrics","method":"get_expected_pod_counts","authorization":"Bwuth0M2TKk1Znm+iD7+Pew2hp4Klq5+eTjGuWEjfn4="},
> "body":{"message_type":"void"} }
>
> 2023-03-17T21:02:30-06:00 2023-03-18 03:02:30,183 INFO
> [net.redpoint.rpdm.artemis_logger.RpdmArtemisLogger] DELIVER: { "header":
> {"version":1,"type":"void","id":"om8xv1gdjvsb","api":"hpa_metrics","method":"get_expected_pod_counts","authorization":"Bwuth0M2TKk1Znm+iD7+Pew2hp4Klq5+eTjGuWEjfn4="},
> "body":{"message_type":"void"} }
>
>
>
> But the response only SEND, no DELIVER:
>
> 2023-03-17T21:02:30-06:00 2023-03-18 03:02:30,305 INFO
> [net.redpoint.rpdm.artemis_logger.RpdmArtemisLogger] SEND: { "header":
> {"version":1,"type":"expected_pod_counts_response","id":"om8xv1gdjvsb","http_code":200},
> "body":{"counts":[{"message_type":"expected_pod_count_response","pod_type":"project_execution","memory_mb":2048,"jvm_memory_mb":250,"count":1},{"message_type":"expected_pod_count_response","pod_type":"project_execution","memory_mb":6144,"jvm_memory_mb":2000,"count":0},{"message_type":"expected_pod_count_response","pod_type":"project_edit","memory_mb":500,"jvm_memory_mb":500,"count":1},{"message_type":"expected_pod_count_response","pod_type":"automation_edit","memory_mb":500,"jvm_memory_mb":500,"count":0},{"message_type":"expected_pod_count_response","pod_type":"automation_execution","memory_mb":500,"jvm_memory_mb":250,"count":0}],"message_type":"expected_pod_counts_response"}
> }
>
>
>
> This is consistent with the reply-to consumer being closed, but I cannot
> how or when it is closed. Also in the AMQ console we see the consumer
> count is zero and there is one message, so it certainly *acts* like the
> reply-to consumer was closed.
>
>
>
> I should mention that we see a lot of these in our RPC client log, but
> since there so many I assumed they were harmless:
>
> 2023-03-18T03:02:36.094 [Thread-2] ClientSessionImpl.close:1333 [] DEBUG -
> Calling close on session ClientSessionImpl
> [name=509b0e84-c539-11ed-911b-86945e7d6721, username=null, closed=false,
> factory =
> org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl@50f3a373,
> metaData=()]@d95cd6d
>
> 2023-03-18T03:02:36.095 [Thread-2] ClientSessionImpl.doCleanup:2080 []
> DEBUG - calling cleanup on ClientSessionImpl
> [name=509b0e84-c539-11ed-911b-86945e7d6721, username=null, closed=false,
> factory =
> org.apache.activemq.artemis.core.client.impl.ClientSessionFactoryImpl@50f3a373,
> metaData=()]@d95cd6d
>
>
>
> I looked back 30 seconds in the RPC client log, and didn’t see anything
> odd, but there is this unusual flurry:
>
> 2023-03-18T03:01:57.255 [HpaMetrics-Background]
> AbstractProducerCreditsImpl.checkCredits:182 [] DEBUG - not asking for -1
> credits on activemq.management
>
> 2023-03-18T03:01:57.255 [HpaMetrics-Background]
> AbstractProducerCreditsImpl.afterAcquired:90 [] DEBUG - AfterAcquire 413
> credits on address activemq.management
>
> 2023-03-18T03:01:57.256 [HpaMetrics-Background]
> AbstractProducerCreditsImpl.checkCredits:182 [] DEBUG - not asking for -1
> credits on activemq.management
>
> 2023-03-18T03:01:57.256 [HpaMetrics-Background]
> AbstractProducerCreditsImpl.afterAcquired:90 [] DEBUG - AfterAcquire 415
> credits on address activemq.management
>
> 2023-03-18T03:01:57.257 [HpaMetrics-Background]
> AbstractProducerCreditsImpl.checkCredits:182 [] DEBUG - not asking for -1
> credits on activemq.management
>
> 2023-03-18T03:01:57.257 [HpaMetrics-Background]
> AbstractProducerCreditsImpl.afterAcquired:90 [] DEBUG - AfterAcquire 389
> credits on address activemq.management
>
> 2023-03-18T03:01:57.257 [HpaMetrics-Background]
> AbstractProducerCreditsImpl.checkCredits:182 [] DEBUG - not asking for -1
> credits on activemq.management
>
> 2023-03-18T03:01:57.257 [HpaMetrics-Background]
> AbstractProducerCreditsImpl.afterAcquired:90 [] DEBUG - AfterAcquire 395
> credits on address activemq.management
>
> 2023-03-18T03:01:57.258 [HpaMetrics-Background]
> AbstractProducerCreditsImpl.checkCredits:182 [] DEBUG - not asking for -1
> credits on activemq.management
>
> 2023-03-18T03:01:57.258 [HpaMetrics-Background]
> AbstractProducerCreditsImpl.afterAcquired:90 [] DEBUG - AfterAcquire 401
> credits on address activemq.management
>
>
>
> Meanwhile, we have a custom logger installed in the AMQ broker, and
> everything looks fine until it is not:
>
>
>
> [image: rg] <https://www.redpointglobal.com/>
>
> John Lilley
>
> Data Management Chief Architect, Redpoint Global Inc.
>
> 888 Worcester Street, Suite 200 Wellesley, MA 02482
>
> *M: *+1 7209385761 <+1%207209385761> | john.lilley@redpointglobal.com
>
> PLEASE NOTE: This e-mail from Redpoint Global Inc. (“Redpoint”) is
> confidential and is intended solely for the use of the individual(s) to
> whom it is addressed. If you believe you received this e-mail in error,
> please notify the sender immediately, delete the e-mail from your computer
> and do not copy, print or disclose it to anyone else. If you properly
> received this e-mail as a customer, partner or vendor of Redpoint, you
> should maintain its contents in confidence subject to the terms and
> conditions of your agreement(s) with Redpoint.
>