AndreasPetersen
commented
1 year ago We restarted our pods, and they started getting the error after about 26 minutes. In the mean time no messages were received. It's not immediately obvious from the logs why no messages were received during those 26 minutes:
2023-04-21 14:17:34,827 INFO [com.azu.cor.amq.imp.ReactorSession] (parallel-1) {} {"az.sdk.message":"Returning existing receive link.","connectionId":"MF_dae54d_1682077900713","linkName":"generate_history_359c54_1682077900924","entityPath":"generate_history"}
2023-04-21 14:17:34,827 INFO [com.azu.mes.ser.imp.ServiceBusReceiveLinkProcessor] (parallel-1) {} Not adding credits. No downstream subscribers or items requested.
2023-04-21 14:17:34,826 INFO [com.azu.mes.ser.imp.ServiceBusReceiveLinkProcessor] (parallel-1) {} {"az.sdk.message":"Setting next AMQP receive link.","linkName":"generate_history_359c54_1682077900924","entityPath":"generate_history"}
2023-04-21 14:17:34,826 INFO [com.azu.mes.ser.imp.ServiceBusReceiveLinkProcessor] (parallel-1) {} Requesting a new AmqpReceiveLink from upstream.
2023-04-21 14:17:30,509 INFO [com.azu.cor.amq.imp.han.ReceiveLinkHandler] (reactor-executor-1) {} {"az.sdk.message":"onLinkRemoteOpen","connectionId":"MF_dae54d_1682077900713","entityPath":"generate_history","linkName":"generate_history_359c54_1682077900924","remoteSource":"Source{address='generate_history', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null, filter=null, defaultOutcome=null, outcomes=null, capabilities=null}"}
2023-04-21 14:17:30,476 INFO [com.azu.cor.amq.imp.ReactorSession] (reactor-executor-1) {} {"az.sdk.message":"Creating a new receiver link.","connectionId":"MF_dae54d_1682077900713","sessionName":"generate_history","linkName":"generate_history_359c54_1682077900924"}
2023-04-21 14:17:30,476 INFO [com.azu.cor.amq.imp.ActiveClientTokenManager] (reactor-executor-1) {} {"az.sdk.message":"Scheduling refresh token task.","scopes":"https://servicebus.azure.net/.default"}
2023-04-21 14:17:30,317 INFO [com.azu.ide.ClientSecretCredential] (Thread-13) {} Azure Identity => getToken() result for scopes [https://servicebus.azure.net/.default]: SUCCESS
2023-04-21 14:17:30,316 INFO [com.mic.aad.msa.AcquireTokenSilentSupplier] (Thread-13) {} Returning token from cache
2023-04-21 14:17:30,314 WARN [com.azu.mes.ser.imp.ServiceBusReceiveLinkProcessor] (boundedElastic-2) {} {"az.sdk.message":"Transient error occurred.","exception":"The link 'G4S2:104094190:generate_history_359c54_1682077900924' is force detached. Code: consumer(link2783). Details: AmqpMessageConsumer.IdleTimerExpired: Idle timeout: 00:10:00. TrackingId:a0c677c10000070c00000adf644278d1_G4S2_B7S1, SystemTracker:G4S2:104094190:generate_history_359c54_1682077900924, Timestamp:2023-04-21T12:17:25, errorContext[NAMESPACE: myservicebus.servicebus.windows.net. ERROR CONTEXT: N/A, PATH: generate_history, REFERENCE_ID: generate_history_359c54_1682077900924, LINK_CREDIT: 0]","linkName":"n/a","entityPath":"n/a","attempt":1,"retryAfter":4511}
2023-04-21 14:17:30,313 INFO [com.azu.mes.ser.imp.ServiceBusReceiveLinkProcessor] (parallel-1) {} Not adding credits. No downstream subscribers or items requested.
2023-04-21 14:17:30,312 INFO [com.azu.mes.ser.imp.ServiceBusReceiveLinkProcessor] (parallel-1) {} {"az.sdk.message":"Setting next AMQP receive link.","linkName":"generate_history_359c54_1682077900924","entityPath":"generate_history"}
2023-04-21 14:17:30,312 INFO [com.azu.mes.ser.imp.ServiceBusReceiveLinkProcessor] (parallel-1) {} Requesting a new AmqpReceiveLink from upstream.
2023-04-21 14:17:25,804 INFO [com.azu.cor.amq.imp.han.ReceiveLinkHandler] (reactor-executor-1) {} {"az.sdk.message":"onLinkFinal","connectionId":"MF_dae54d_1682077900713","linkName":"generate_history_359c54_1682077900924","entityPath":"generate_history"}
2023-04-21 14:17:25,800 WARN [com.azu.mes.ser.imp.ServiceBusReceiveLinkProcessor] (reactor-executor-1) {} {"az.sdk.message":"Transient error occurred.","exception":"The link 'G4S2:104094190:generate_history_359c54_1682077900924' is force detached. Code: consumer(link2783). Details: AmqpMessageConsumer.IdleTimerExpired: Idle timeout: 00:10:00. TrackingId:a0c677c10000070c00000adf644278d1_G4S2_B7S1, SystemTracker:G4S2:104094190:generate_history_359c54_1682077900924, Timestamp:2023-04-21T12:17:25, errorContext[NAMESPACE: myservicebus.servicebus.windows.net. ERROR CONTEXT: N/A, PATH: generate_history, REFERENCE_ID: generate_history_359c54_1682077900924, LINK_CREDIT: 0]","linkName":"n/a","entityPath":"n/a","attempt":1,"retryAfter":4511}
2023-04-21 14:17:25,797 INFO [com.azu.cor.amq.imp.ReactorReceiver] (reactor-executor-1) {} {"az.sdk.message":"Freeing resources due to error.","connectionId":"MF_dae54d_1682077900713","entityPath":"generate_history","linkName":"generate_history_359c54_1682077900924"}
2023-04-21 14:17:25,795 INFO [com.azu.cor.amq.imp.han.ReceiveLinkHandler] (reactor-executor-1) {} {"az.sdk.message":"Local link state is not closed.","connectionId":"MF_dae54d_1682077900713","linkName":"generate_history_359c54_1682077900924","entityPath":"generate_history","state":"ACTIVE"}
2023-04-21 14:17:25,794 INFO [com.azu.cor.amq.imp.han.ReceiveLinkHandler] (reactor-executor-1) {} {"az.sdk.message":"onLinkRemoteClose","connectionId":"MF_dae54d_1682077900713","errorCondition":"amqp:link:detach-forced","errorDescription":"The link 'G4S2:104094190:generate_history_359c54_1682077900924' is force detached. Code: consumer(link2783). Details: AmqpMessageConsumer.IdleTimerExpired: Idle timeout: 00:10:00. TrackingId:a0c677c10000070c00000adf644278d1_G4S2_B7S1, SystemTracker:G4S2:104094190:generate_history_359c54_1682077900924, Timestamp:2023-04-21T12:17:25","linkName":"generate_history_359c54_1682077900924","entityPath":"generate_history"}
2023-04-21 13:57:11,643 INFO [com.azu.cor.amq.imp.ActiveClientTokenManager] (reactor-executor-1) {} {"az.sdk.message":"Scheduling refresh token task.","scopes":"https://servicebus.azure.net/.default"}
2023-04-21 13:57:11,610 INFO [com.azu.cor.amq.imp.han.ReceiveLinkHandler] (reactor-executor-1) {} {"az.sdk.message":"onLinkRemoteOpen","connectionId":"MF_dae54d_1682077900713","entityPath":"generate_history/$management","linkName":"generate_history-mgmt:receiver","remoteSource":"Source{address='generate_history/$management', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null, filter=null, defaultOutcome=null, outcomes=null, capabilities=null}"}
2023-04-21 13:57:11,610 INFO [com.azu.cor.amq.imp.AmqpChannelProcessor] (reactor-executor-1) {} {"az.sdk.message":"Channel is now active.","connectionId":"MF_dae54d_1682077900713","entityPath":"generate_history/$management"}
2023-04-21 13:57:11,609 INFO [com.azu.cor.amq.imp.han.SendLinkHandler] (reactor-executor-1) {} {"az.sdk.message":"onLinkRemoteOpen","connectionId":"MF_dae54d_1682077900713","linkName":"generate_history-mgmt:sender","entityPath":"generate_history/$management","remoteTarget":"Target{address='generate_history/$management', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null}"}
2023-04-21 13:57:11,557 INFO [com.azu.cor.amq.imp.AmqpChannelProcessor] (reactor-executor-1) {} {"az.sdk.message":"Setting next AMQP channel.","connectionId":"MF_dae54d_1682077900713","entityPath":"generate_history/$management"}
2023-04-21 13:57:11,557 INFO [com.azu.cor.amq.imp.ReactorConnection] (reactor-executor-1) {} {"az.sdk.message":"Emitting new response channel.","connectionId":"MF_dae54d_1682077900713","entityPath":"generate_history/$management","linkName":"generate_history-mgmt"}
2023-04-21 13:57:11,556 INFO [com.azu.cor.amq.imp.han.SessionHandler] (reactor-executor-1) {} {"az.sdk.message":"onSessionRemoteOpen","connectionId":"MF_dae54d_1682077900713","sessionName":"generate_history-mgmt-session","sessionIncCapacity":0,"sessionOutgoingWindow":2147483647}
2023-04-21 13:57:11,526 INFO [com.azu.ide.ClientSecretCredential] (Thread-12) {} Azure Identity => getToken() result for scopes [https://servicebus.azure.net/.default]: SUCCESS
2023-04-21 13:57:11,525 INFO [com.mic.aad.msa.AcquireTokenSilentSupplier] (Thread-12) {} Returning token from cache
2023-04-21 13:57:11,521 INFO [com.azu.mes.ser.imp.ServiceBusReactorAmqpConnection] (parallel-1) {} {"az.sdk.message":"Creating management node.","linkName":"generate_history-mgmt","entityPath":"generate_history","address":"generate_history/$management"}
2023-04-21 13:56:21,620 INFO [io.sma.rea.mes.pro.con.WorkerPoolRegistry] (vert.x-eventloop-thread-1) {parentId=f4809c95849bfe18, sampled=true, spanId=7a75c206b98c9acb, traceId=c57ab1e64e936ae2b893a8cff3ec20e6} Created worker pool named in-history with concurrency of 20
2023-04-21 13:51:45,291 INFO [com.azu.cor.amq.imp.han.ReceiveLinkHandler] (reactor-executor-1) {} {"az.sdk.message":"onLinkRemoteOpen","connectionId":"MF_dae54d_1682077900713","entityPath":"generate_history","linkName":"generate_history_359c54_1682077900924","remoteSource":"Source{address='generate_history', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null, filter=null, defaultOutcome=null, outcomes=null, capabilities=null}"}
2023-04-21 13:51:45,238 INFO [com.azu.cor.amq.imp.ReactorSession] (reactor-executor-1) {} {"az.sdk.message":"Returning existing receive link.","connectionId":"MF_dae54d_1682077900713","linkName":"generate_history_359c54_1682077900924","entityPath":"generate_history"}
2023-04-21 13:51:45,220 INFO [com.azu.mes.ser.imp.ServiceBusReceiveLinkProcessor] (reactor-executor-1) {} {"az.sdk.message":"Setting next AMQP receive link.","linkName":"generate_history_359c54_1682077900924","entityPath":"generate_history"}
2023-04-21 13:51:45,210 INFO [com.azu.cor.amq.imp.ReactorSession] (reactor-executor-1) {} {"az.sdk.message":"Creating a new receiver link.","connectionId":"MF_dae54d_1682077900713","sessionName":"generate_history","linkName":"generate_history_359c54_1682077900924"}
2023-04-21 13:51:45,204 INFO [com.azu.cor.amq.imp.ActiveClientTokenManager] (reactor-executor-1) {} {"az.sdk.message":"Scheduling refresh token task.","scopes":"https://servicebus.azure.net/.default"}
2023-04-21 13:51:45,029 INFO [com.azu.ide.ClientSecretCredential] (Thread-10) {} Azure Identity => getToken() result for scopes [https://servicebus.azure.net/.default]: SUCCESS
2023-04-21 13:51:43,315 INFO [com.azu.cor.amq.imp.han.ReceiveLinkHandler] (reactor-executor-1) {} {"az.sdk.message":"onLinkRemoteOpen","connectionId":"MF_dae54d_1682077900713","entityPath":"$cbs","linkName":"cbs:receiver","remoteSource":"Source{address='$cbs', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, distributionMode=null, filter=null, defaultOutcome=null, outcomes=null, capabilities=null}"}
2023-04-21 13:51:43,315 INFO [com.azu.cor.amq.imp.AmqpChannelProcessor] (reactor-executor-1) {} {"az.sdk.message":"Channel is now active.","connectionId":"MF_dae54d_1682077900713","entityPath":"$cbs"}
2023-04-21 13:51:43,312 INFO [com.azu.cor.amq.imp.han.SendLinkHandler] (reactor-executor-1) {} {"az.sdk.message":"onLinkRemoteOpen","connectionId":"MF_dae54d_1682077900713","linkName":"cbs:sender","entityPath":"$cbs","remoteTarget":"Target{address='$cbs', durable=NONE, expiryPolicy=SESSION_END, timeout=0, dynamic=false, dynamicNodeProperties=null, capabilities=null}"}
2023-04-21 13:51:43,221 INFO [com.azu.cor.amq.imp.AmqpChannelProcessor] (reactor-executor-1) {} {"az.sdk.message":"Next AMQP channel received.","connectionId":"MF_dae54d_1682077900713","entityPath":"$cbs","subscriberId":"un_dab5d5_1682077903038"}
2023-04-21 13:51:43,138 INFO [com.azu.cor.uti.tra.DefaultTracerProvider] (reactor-executor-1) {} Found Tracer implementation on the classpath: com.azure.core.tracing.opentelemetry.OpenTelemetryTracer
2023-04-21 13:51:43,076 INFO [com.azu.cor.amq.imp.AmqpChannelProcessor] (reactor-executor-1) {} {"az.sdk.message":"Setting next AMQP channel.","connectionId":"MF_dae54d_1682077900713","entityPath":"$cbs"}
2023-04-21 13:51:43,075 INFO [com.azu.cor.amq.imp.ReactorConnection] (reactor-executor-1) {} {"az.sdk.message":"Emitting new response channel.","connectionId":"MF_dae54d_1682077900713","entityPath":"$cbs","linkName":"cbs"}
2023-04-21 13:51:43,067 INFO [com.azu.cor.amq.imp.han.SessionHandler] (reactor-executor-1) {} {"az.sdk.message":"onSessionRemoteOpen","connectionId":"MF_dae54d_1682077900713","sessionName":"cbs-session","sessionIncCapacity":0,"sessionOutgoingWindow":2147483647}
2023-04-21 13:51:43,034 INFO [com.azu.cor.amq.imp.ReactorConnection] (reactor-executor-1) {} {"az.sdk.message":"Setting CBS channel.","connectionId":"MF_dae54d_1682077900713"}
2023-04-21 13:51:43,023 INFO [com.azu.cor.amq.imp.han.SessionHandler] (reactor-executor-1) {} {"az.sdk.message":"onSessionRemoteOpen","connectionId":"MF_dae54d_1682077900713","sessionName":"generate_history","sessionIncCapacity":0,"sessionOutgoingWindow":2147483647}
2023-04-21 13:51:42,974 INFO [com.azu.mes.ser.imp.ServiceBusConnectionProcessor] (reactor-executor-1) {} {"az.sdk.message":"Channel is now active.","entityPath":"N/A"}
2023-04-21 13:51:42,974 INFO [com.azu.cor.amq.imp.han.WebSocketsConnectionHandler] (reactor-executor-1) {} {"az.sdk.message":"onConnectionRemoteOpen","connectionId":"MF_dae54d_1682077900713","hostName":"myservicebus.servicebus.windows.net","remoteContainer":"b885d5a5383f454db026bc00e6a84e14_G4S2"}
2023-04-21 13:51:42,830 INFO [io.quarkus] (main) {} Installed features: [agroal, cache, cdi, cxf, hibernate-orm, jdbc-db2, micrometer, narayana-jta, opentelemetry, opentelemetry-otlp-exporter, reactive-routes, rest-client-reactive, rest-client-reactive-jackson, resteasy-reactive, resteasy-reactive-jackson, security, smallrye-context-propagation, smallrye-fault-tolerance, smallrye-health, smallrye-jwt, smallrye-openapi, smallrye-reactive-messaging, swagger-ui, vertx]
2023-04-21 13:51:42,830 INFO [io.quarkus] (main) {} Profile prod activated.
2023-04-21 13:51:42,830 INFO [io.quarkus] (main) {} wealth-items-service a96a4b2c49 on JVM (powered by Quarkus 2.16.4.Final) started in 18.805s. Listening on: http://0.0.0.0:8080
2023-04-21 13:51:41,421 INFO [com.azu.cor.amq.imp.han.WebSocketsConnectionHandler] (reactor-executor-1) {} {"az.sdk.message":"Adding web socket layer","connectionId":"MF_dae54d_1682077900713"}
2023-04-21 13:51:41,420 INFO [com.azu.cor.amq.imp.han.WebSocketsConnectionHandler] (reactor-executor-1) {} {"az.sdk.message":"onConnectionBound","connectionId":"MF_dae54d_1682077900713","hostName":"myservicebus.servicebus.windows.net","peerDetails":"myservicebus.servicebus.windows.net:443"}
2023-04-21 13:51:41,325 INFO [com.azu.mes.ser.ServiceBusClientBuilder] (main) {} # of open clients with shared connection: 1
2023-04-21 13:51:41,324 INFO [com.azu.mes.ser.imp.ServiceBusConnectionProcessor] (main) {} {"az.sdk.message":"Setting next AMQP channel.","entityPath":"N/A"}
2023-04-21 13:51:41,323 INFO [com.azu.cor.amq.ProxyOptions] (main) {} Username or password is null. Using system-wide authentication.
2023-04-21 13:51:41,116 INFO [com.azu.cor.amq.imp.han.WebSocketsConnectionHandler] (reactor-executor-1) {} {"az.sdk.message":"onConnectionLocalOpen","connectionId":"MF_dae54d_1682077900713","errorCondition":null,"errorDescription":null,"hostName":"myservicebus.servicebus.windows.net"}
2023-04-21 13:51:41,115 INFO [com.azu.cor.amq.imp.han.ReactorHandler] (reactor-executor-1) {} {"az.sdk.message":"reactor.onReactorInit","connectionId":"MF_dae54d_1682077900713"}
2023-04-21 13:51:41,114 INFO [com.azu.cor.amq.imp.han.WebSocketsConnectionHandler] (reactor-executor-1) {} {"az.sdk.message":"onConnectionInit","connectionId":"MF_dae54d_1682077900713","hostName":"myservicebus.servicebus.windows.net","namespace":"myservicebus.servicebus.windows.net"}
2023-04-21 13:51:41,037 INFO [com.azu.cor.amq.imp.ReactorExecutor] (main) {} {"az.sdk.message":"Starting reactor.","connectionId":"MF_dae54d_1682077900713"}
2023-04-21 13:51:41,022 INFO [com.azu.cor.amq.imp.ReactorConnection] (main) {} {"az.sdk.message":"Creating and starting connection.","connectionId":"MF_dae54d_1682077900713","hostName":"myservicebus.servicebus.windows.net","port":443}
2023-04-21 13:51:40,930 INFO [com.azu.mes.ser.imp.ServiceBusReceiveLinkProcessor] (main) {} Requesting a new AmqpReceiveLink from upstream.
2023-04-21 13:51:40,924 INFO [com.azu.mes.ser.ServiceBusReceiverAsyncClient] (main) {} {"az.sdk.message":"Creating consumer.","linkName":"generate_history_359c54_1682077900924","entityPath":"generate_history"}
2023-04-21 13:51:40,835 INFO [com.azu.mes.ser.ServiceBusClientBuilder] (main) {} # of open clients with shared connection: 1
2023-04-21 13:51:40,832 INFO [com.azu.mes.ser.imp.ServiceBusConnectionProcessor] (main) {} {"az.sdk.message":"Setting next AMQP channel.","entityPath":"N/A"}
2023-04-21 13:51:40,424 INFO [com.azu.cor.amq.ProxyOptions] (main) {} Username or password is null. Using system-wide authentication.
2023-04-21 13:51:39,229 INFO [io.qua.sma.ope.run.OpenApiRecorder] (main) {} CORS filtering is disabled and cross-origin resource sharing is allowed without restriction, which is not recommended in production. Please configure the CORS filter through 'quarkus.http.cors.*' properties. For more information, see Quarkus HTTP CORS documentation
2023-04-21 13:51:38,824 INFO [io.mic.cor.ins.pus.PushMeterRegistry] (main) {} publishing metrics for OtlpMeterRegistry every 1m
2023-04-21 13:51:27,114 WARN [io.qua.config] (main) {} Unrecognized configuration key "quarkus.cxf.client.timeout" was provided; it will be ignored; verify that the dependency extension for this configuration is set or that you did not make a typo
--\___\_\____/_/ |_/_/|_/_/|_|\____/___/
-/ /_/ / /_/ / __ |/ , _/ ,< / /_/ /\ \
--/ __ \/ / / / _ | / _ \/ //_/ / / / __/
__ ____ __ _____ ___ __ ____ ______
Picked up JAVA_TOOL_OPTIONS: -XX:+UseG1GC -XX:+UseContainerSupport -XX:MinRAMPercentage=50.0 -XX:MaxRAMPercentage=25.0
joshfree
anuchandy
Describe the bug After running our service since 2023-04-19 around 15:00, on 2023-04-20 at around 12:40 our services stops receiving messages. There are no warning or error messages saying why. At 16:57 the services starts receiving the errors below. This continues until at least 2023-04-21 10:00 where I'm writing this bug report. Meanwhile no new messages are received.
We are running two pods on a Kubernetes cluster, and the error occurred on both pods at the same time.
I can see that there are related issues reported, but these are closed and locked: #18890, #32919
Exception or Stack Trace Specifically the warning/error logs. The rest are included for context.
The errors occurs every 10 minutes.
To Reproduce Steps to reproduce the behavior:
Unknown
Code Snippet
Expected behavior Being able to re-establish connection and continue receiving messages.
Setup (please complete the following information):
com.azure:azure-messaging-servicebus:7.13.0andcom.azure:azure-identity:1.5.4Information Checklist Kindly make sure that you have added all the following information above and checkoff the required fields otherwise we will treat the issuer as an incomplete report