search

Azure / azure-sdk-for-java

This repository is for active development of the Azure SDK for Java. For consumers of the SDK we recommend visiting our public developer docs at https://docs.microsoft.com/java/azure/ or our versioned developer docs at https://azure.github.io/azure-sdk-for-java.
MIT License
2.35k stars 1.99k forks source link

[BUG] [1] [parallel-2] [] [reactor.util.Loggers$Slf4JLogger] - Operator called default onErrorDropped reactor.core.Exceptions$ErrorCallbackNotImplemented: java.lang.NullPointerException Caused by: java.lang.NullPointerException #42987

Open dineshlalwani opened 4 hours ago

dineshlalwani commented 4 hours ago

Describe the bug We're using streamBridge.send(bindingName, MessageBuilder.withPayload(payload).build()) to send messages in ASB Queues, it is maximizing our CPU usage and ultimately crashing the service because of [reactor-executor-XXXX] thread leaks.

Exception or Stack Trace

[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"onSessionRemoteClose","connectionId":"MF_6adc03_1731309919739","errorCondition":"amqp:connection:forced","errorDescription":"The connection was closed by container '4fc9165857464070a1d8ebe127ce71d8_G2' because it did not have any active links in the past 300000 milliseconds. TrackingId:4fc9165857464070a1d8ebe127ce71d8_G2, SystemTracker:gateway5, Timestamp:2024-11-11T08:39:31","sessionName":"session_Name"}
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"onSessionRemoteClose closing a local session.","connectionId":"MF_6adc03_1731309919739","errorCondition":"amqp:connection:forced","errorDescription":"The connection was closed by container '4fc9165857464070a1d8ebe127ce71d8_G2' because it did not have any active links in the past 300000 milliseconds. TrackingId:4fc9165857464070a1d8ebe127ce71d8_G2, SystemTracker:gateway5, Timestamp:2024-11-11T08:39:31","sessionName":"session_Name"}
[2024-11-11 08:39:31.031] [ERROR] [1] [reactor-executor-1854] [] [reactor.util.Loggers$Slf4JLogger] - Operator called default onErrorDropped
reactor.core.Exceptions$ErrorCallbackNotImplemented: com.azure.core.amqp.exception.AmqpException: onSessionRemoteClose connectionId[MF_6adc03_1731309919739], entityName[entity_name] condition[Error{condition=amqp:connection:forced, description='The connection was closed by container '4fc9165857464070a1d8ebe127ce71d8_G2' because it did not have any active links in the past 300000 milliseconds. TrackingId:4fc9165857464070a1d8ebe127ce71d8_G2, SystemTracker:gateway5, Timestamp:2024-11-11T08:39:31', info=null}], errorContext[NAMESPACE: host_name. ERROR CONTEXT: N/A, PATH: entity_name]
Caused by: com.azure.core.amqp.exception.AmqpException: onSessionRemoteClose connectionId[MF_6adc03_1731309919739], entityName[entity_name] condition[Error{condition=amqp:connection:forced, description='The connection was closed by container '4fc9165857464070a1d8ebe127ce71d8_G2' because it did not have any active links in the past 300000 milliseconds. TrackingId:4fc9165857464070a1d8ebe127ce71d8_G2, SystemTracker:gateway5, Timestamp:2024-11-11T08:39:31', info=null}], errorContext[NAMESPACE: host_name. ERROR CONTEXT: N/A, PATH: entity_name]
    at com.azure.core.amqp.implementation.ExceptionUtil.toException(ExceptionUtil.java:85) ~[azure-core-amqp-2.8.8.jar!/:2.8.8]
    at com.azure.core.amqp.implementation.handler.SessionHandler.onSessionRemoteClose(SessionHandler.java:136) ~[azure-core-amqp-2.8.8.jar!/:2.8.8]
    at org.apache.qpid.proton.engine.BaseHandler.handle(BaseHandler.java:152) ~[proton-j-0.33.8.jar!/:?]
    at org.apache.qpid.proton.engine.impl.EventImpl.dispatch(EventImpl.java:108) ~[proton-j-0.33.8.jar!/:?]
    at org.apache.qpid.proton.reactor.impl.ReactorImpl.dispatch(ReactorImpl.java:324) ~[proton-j-0.33.8.jar!/:?]
    at org.apache.qpid.proton.reactor.impl.ReactorImpl.process(ReactorImpl.java:291) ~[proton-j-0.33.8.jar!/:?]
    at com.azure.core.amqp.implementation.ReactorExecutor.run(ReactorExecutor.java:91) ~[azure-core-amqp-2.8.8.jar!/:2.8.8]
    at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:68) [reactor-core-3.5.7.jar!/:3.5.7]
    at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:28) [reactor-core-3.5.7.jar!/:3.5.7]
    at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
    at java.lang.Thread.run(Thread.java:833) [?:?]
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"Error occurred. Removing and disposing session","exception":"onSessionRemoteClose connectionId[MF_6adc03_1731309919739], entityName[entity_name] condition[Error{condition=amqp:connection:forced, description='The connection was closed by container '4fc9165857464070a1d8ebe127ce71d8_G2' because it did not have any active links in the past 300000 milliseconds. TrackingId:4fc9165857464070a1d8ebe127ce71d8_G2, SystemTracker:gateway5, Timestamp:2024-11-11T08:39:31', info=null}], errorContext[NAMESPACE: host_name. ERROR CONTEXT: N/A, PATH: entity_name]","connectionId":"MF_6adc03_1731309919739","sessionName":"session_Name"}
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"onLinkRemoteClose","connectionId":"MF_6adc03_1731309919739","errorCondition":"amqp:connection:forced","errorDescription":"The connection was closed by container '4fc9165857464070a1d8ebe127ce71d8_G2' because it did not have any active links in the past 300000 milliseconds. TrackingId:4fc9165857464070a1d8ebe127ce71d8_G2, SystemTracker:gateway5, Timestamp:2024-11-11T08:39:31","linkName":"cbs:sender","entityPath":"$cbs"}
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"Local link state is not closed.","connectionId":"MF_6adc03_1731309919739","linkName":"cbs:sender","entityPath":"$cbs","state":"ACTIVE"}
[2024-11-11 08:39:31.031] [WARN ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"Error in SendLinkHandler. Disposing unconfirmed sends.","exception":"The connection was closed by container '4fc9165857464070a1d8ebe127ce71d8_G2' because it did not have any active links in the past 300000 milliseconds. TrackingId:4fc9165857464070a1d8ebe127ce71d8_G2, SystemTracker:gateway5, Timestamp:2024-11-11T08:39:31, errorContext[NAMESPACE: host_name. ERROR CONTEXT: N/A, PATH: $cbs, REFERENCE_ID: cbs:sender, LINK_CREDIT: 97]","connectionId":"MF_6adc03_1731309919739","linkName":"cbs"}
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"Transient error occurred. Retrying.","exception":"The connection was closed by container '4fc9165857464070a1d8ebe127ce71d8_G2' because it did not have any active links in the past 300000 milliseconds. TrackingId:4fc9165857464070a1d8ebe127ce71d8_G2, SystemTracker:gateway5, Timestamp:2024-11-11T08:39:31, errorContext[NAMESPACE: host_name. ERROR CONTEXT: N/A, PATH: $cbs, REFERENCE_ID: cbs:sender, LINK_CREDIT: 97]","connectionId":"MF_6adc03_1731309919739","entityPath":"$cbs","tryCount":0,"interval_ms":4511}
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"onLinkRemoteClose","connectionId":"MF_6adc03_1731309919739","errorCondition":"amqp:connection:forced","errorDescription":"The connection was closed by container '4fc9165857464070a1d8ebe127ce71d8_G2' because it did not have any active links in the past 300000 milliseconds. TrackingId:4fc9165857464070a1d8ebe127ce71d8_G2, SystemTracker:gateway5, Timestamp:2024-11-11T08:39:31","linkName":"cbs:receiver","entityPath":"$cbs"}
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"Local link state is not closed.","connectionId":"MF_6adc03_1731309919739","linkName":"cbs:receiver","entityPath":"$cbs","state":"ACTIVE"}
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"onSessionRemoteClose","connectionId":"MF_6adc03_1731309919739","errorCondition":"amqp:connection:forced","errorDescription":"The connection was closed by container '4fc9165857464070a1d8ebe127ce71d8_G2' because it did not have any active links in the past 300000 milliseconds. TrackingId:4fc9165857464070a1d8ebe127ce71d8_G2, SystemTracker:gateway5, Timestamp:2024-11-11T08:39:31","sessionName":"xyz-session"}
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"onSessionRemoteClose closing a local session.","connectionId":"MF_6adc03_1731309919739","errorCondition":"amqp:connection:forced","errorDescription":"The connection was closed by container '4fc9165857464070a1d8ebe127ce71d8_G2' because it did not have any active links in the past 300000 milliseconds. TrackingId:4fc9165857464070a1d8ebe127ce71d8_G2, SystemTracker:gateway5, Timestamp:2024-11-11T08:39:31","sessionName":"xyz-session"}
[2024-11-11 08:39:31.031] [ERROR] [1] [reactor-executor-1854] [] [reactor.util.Loggers$Slf4JLogger] - Operator called default onErrorDropped
reactor.core.Exceptions$ErrorCallbackNotImplemented: com.azure.core.amqp.exception.AmqpException: onSessionRemoteClose connectionId[MF_6adc03_1731309919739], entityName[cbs-session] condition[Error{condition=amqp:connection:forced, description='The connection was closed by container '4fc9165857464070a1d8ebe127ce71d8_G2' because it did not have any active links in the past 300000 milliseconds. TrackingId:4fc9165857464070a1d8ebe127ce71d8_G2, SystemTracker:gateway5, Timestamp:2024-11-11T08:39:31', info=null}], errorContext[NAMESPACE: host_name. ERROR CONTEXT: N/A, PATH: cbs-session]
Caused by: com.azure.core.amqp.exception.AmqpException: onSessionRemoteClose connectionId[MF_6adc03_1731309919739], entityName[cbs-session] condition[Error{condition=amqp:connection:forced, description='The connection was closed by container '4fc9165857464070a1d8ebe127ce71d8_G2' because it did not have any active links in the past 300000 milliseconds. TrackingId:4fc9165857464070a1d8ebe127ce71d8_G2, SystemTracker:gateway5, Timestamp:2024-11-11T08:39:31', info=null}], errorContext[NAMESPACE: host_name. ERROR CONTEXT: N/A, PATH: cbs-session]
    at com.azure.core.amqp.implementation.ExceptionUtil.toException(ExceptionUtil.java:85) ~[azure-core-amqp-2.8.8.jar!/:2.8.8]
    at com.azure.core.amqp.implementation.handler.SessionHandler.onSessionRemoteClose(SessionHandler.java:136) ~[azure-core-amqp-2.8.8.jar!/:2.8.8]
    at org.apache.qpid.proton.engine.BaseHandler.handle(BaseHandler.java:152) ~[proton-j-0.33.8.jar!/:?]
    at org.apache.qpid.proton.engine.impl.EventImpl.dispatch(EventImpl.java:108) ~[proton-j-0.33.8.jar!/:?]
    at org.apache.qpid.proton.reactor.impl.ReactorImpl.dispatch(ReactorImpl.java:324) ~[proton-j-0.33.8.jar!/:?]
    at org.apache.qpid.proton.reactor.impl.ReactorImpl.process(ReactorImpl.java:291) ~[proton-j-0.33.8.jar!/:?]
    at com.azure.core.amqp.implementation.ReactorExecutor.run(ReactorExecutor.java:91) ~[azure-core-amqp-2.8.8.jar!/:2.8.8]
    at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:68) [reactor-core-3.5.7.jar!/:3.5.7]
    at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:28) [reactor-core-3.5.7.jar!/:3.5.7]
    at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
    at java.lang.Thread.run(Thread.java:833) [?:?]
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"Error occurred. Removing and disposing session","exception":"onSessionRemoteClose connectionId[MF_6adc03_1731309919739], entityName[cbs-session] condition[Error{condition=amqp:connection:forced, description='The connection was closed by container '4fc9165857464070a1d8ebe127ce71d8_G2' because it did not have any active links in the past 300000 milliseconds. TrackingId:4fc9165857464070a1d8ebe127ce71d8_G2, SystemTracker:gateway5, Timestamp:2024-11-11T08:39:31', info=null}], errorContext[NAMESPACE: host_name. ERROR CONTEXT: N/A, PATH: cbs-session]","connectionId":"MF_6adc03_1731309919739","sessionName":"xyz-session"}
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"onConnectionRemoteClose","connectionId":"MF_6adc03_1731309919739","errorCondition":"amqp:connection:forced","errorDescription":"The connection was closed by container '4fc9165857464070a1d8ebe127ce71d8_G2' because it did not have any active links in the past 300000 milliseconds. TrackingId:4fc9165857464070a1d8ebe127ce71d8_G2, SystemTracker:gateway5, Timestamp:2024-11-11T08:39:31","hostName":"host_name"}
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"onTransportClosed","connectionId":"MF_6adc03_1731309919739","hostName":"host_name"}
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"onTransportClosed","connectionId":"MF_6adc03_1731309919739","hostName":"host_name"}
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"onConnectionLocalClose","connectionId":"MF_6adc03_1731309919739","hostName":"host_name"}
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"onConnectionUnbound","connectionId":"MF_6adc03_1731309919739","hostName":"host_name","state":"CLOSED","remoteState":"CLOSED"}
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"Disposing of ReactorConnection.","connectionId":"MF_6adc03_1731309919739","isTransient":false,"isInitiatedByClient":false,"shutdownMessage":"Connection handler closed."}
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"Channel is closed. Requesting upstream.","entityPath":"N/A"}
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"Connection not requested, yet. Requesting one.","entityPath":"N/A"}
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"Setting next AMQP channel.","entityPath":"N/A"}
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"onLinkFinal","connectionId":"MF_6adc03_1731309919739","linkName":"entity_nameentity_name","entityPath":"entity_name"}
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"onLinkFinal","connectionId":"MF_6adc03_1731309919739","linkName":"entity_nameentity_name","entityPath":"entity_name"}
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"onSessionFinal.","connectionId":"MF_6adc03_1731309919739","errorCondition":"amqp:connection:forced","errorDescription":"The connection was closed by container '4fc9165857464070a1d8ebe127ce71d8_G2' because it did not have any active links in the past 300000 milliseconds. TrackingId:4fc9165857464070a1d8ebe127ce71d8_G2, SystemTracker:gateway5, Timestamp:2024-11-11T08:39:31","sessionName":"session_Name"}
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"onLinkFinal","connectionId":"MF_6adc03_1731309919739","linkName":"cbs:sender","entityPath":"$cbs"}
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"onLinkFinal","connectionId":"MF_6adc03_1731309919739","linkName":"cbs:receiver","entityPath":"$cbs"}
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"onSessionFinal.","connectionId":"MF_6adc03_1731309919739","errorCondition":"amqp:connection:forced","errorDescription":"The connection was closed by container '4fc9165857464070a1d8ebe127ce71d8_G2' because it did not have any active links in the past 300000 milliseconds. TrackingId:4fc9165857464070a1d8ebe127ce71d8_G2, SystemTracker:gateway5, Timestamp:2024-11-11T08:39:31","sessionName":"xyz-session"}
[2024-11-11 08:39:31.031] [INFO ] [1] [reactor-executor-1854] [] [com.azure.core.util.logging.LoggingEventBuilder] - {"az.sdk.message":"onConnectionFinal","connectionId":"MF_6adc03_1731309919739","hostName":"host_name"}

Code Snippet We're using StreamBridge to send message over ASB Queues, whenever it comes in idle state we receive The connection was closed by container 'container_name' because it did not have any active links in the past 300000 milliseconds. TrackingId:tracking_id, SystemTracker:System_Tracker, Timestamp:2024-11-11T08:39:31', info=null

Expected behavior It should not throw NPE and prevents thread leak

Setup (please complete the following information):

Information 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

dineshlalwani commented 4 hours ago

Dependencies

+- com.azure.spring:spring-cloud-azure-stream-binder-servicebus:jar:5.5.0:compile [INFO] | +- com.azure.spring:spring-cloud-azure-stream-binder-servicebus-core:jar:5.5.0:compile [INFO] | | +- org.springframework.cloud:spring-cloud-stream:jar:4.0.4:compile [INFO] | | | +- org.springframework.boot:spring-boot-starter-validation:jar:3.1.1:compile [INFO] | | | | - org.hibernate.validator:hibernate-validator:jar:8.0.0.Final:compile [INFO] | | | | +- org.jboss.logging:jboss-logging:jar:3.5.1.Final:compile [INFO] | | | | - com.fasterxml:classmate:jar:1.5.1:compile [INFO] | | | +- org.springframework:spring-messaging:jar:6.0.10:compile [INFO] | | | +- org.springframework.integration:spring-integration-core:jar:6.1.1:compile [INFO] | | | +- org.springframework.integration:spring-integration-jmx:jar:6.1.1:compile [INFO] | | | +- org.springframework.cloud:spring-cloud-function-context:jar:4.1.3:compile [INFO] | | | | +- net.jodah:typetools:jar:0.6.2:compile [INFO] | | | | - org.springframework.cloud:spring-cloud-function-core:jar:4.1.3:compile [INFO] | | | - org.jetbrains.kotlin:kotlin-stdlib-jdk8:jar:1.8.22:compile [INFO] | | | - org.jetbrains.kotlin:kotlin-stdlib-jdk7:jar:1.8.22:compile [INFO] | | +- com.azure.spring:spring-integration-azure-servicebus:jar:5.5.0:compile [INFO] | | | +- com.azure.spring:spring-integration-azure-core:jar:5.5.0:compile [INFO] | | | | - com.azure.spring:spring-messaging-azure:jar:5.5.0:compile [INFO] | | | - com.azure.spring:spring-messaging-azure-servicebus:jar:5.5.0:compile [INFO] | | - com.azure:azure-messaging-servicebus:jar:7.14.3:compile [INFO] | | - com.azure:azure-core-amqp:jar:2.8.8:compile [INFO] | | +- com.microsoft.azure:qpid-proton-j-extensions:jar:1.2.4:compile [INFO] | | - org.apache.qpid:proton-j:jar:0.33.8:compile [

alzimmermsft commented 1 minute ago

Thank you for filing this @dineshlalwani.

@anuchandy, @conniey could you check if this is an issue from azure-core-amqp or an issue in the Spring binder?