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 <john.lil...@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<mailto: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<mailto: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: > > > >[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.lil...@redpointglobal.com<mailto:john.lil...@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.lil...@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.
