Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[BUG] Drain excess credits when using sessions to ensure FIFO (#40457) - Timeout and Session Lock Expiration #41827

Closed
Yello001 opened this issue Feb 7, 2024 · 7 comments · Fixed by #41920
Closed

[BUG] Drain excess credits when using sessions to ensure FIFO (#40457) - Timeout and Session Lock Expiration #41827

Yello001 opened this issue Feb 7, 2024 · 7 comments · Fixed by #41920
Assignees
@jsquire @JoshLove-msft
Labels
Client This issue points to a problem in the data-plane of the library. customer-reported Issues that are reported by GitHub users external to the Azure organization. needs-team-attention This issue needs attention from Azure service team or SDK team question The issue doesn't require a change to the product in order to be resolved. Most issues start as that Service Bus

Comments

@Yello001
Copy link

Yello001 commented Feb 7, 2024 •
edited

Library name and version

Azure.Messaging.ServiceBus 7.17.1, 7.17.2

Describe the bug

#40457 seems to run into a timeout when calling

await link.DrainAsyc(cancellationToken).ConfigureAwait(false);
System.TimeoutException: The operation did not complete within the allocated time 00:01:00 for object drain.
at Microsoft.Azure.Amqp.ExceptionDispatcher.Throw(Exception exception)
at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result)
at Microsoft.Azure.Amqp.ReceivingAmqpLink.DrainAsyncResult.End(IAsyncResult result)
at Microsoft.Azure.Amqp.ReceivingAmqpLink.<>c.b__35_1(IAsyncResult r)
at System.Threading.Tasks.TaskFactory1.FromAsyncCoreLogic(IAsyncResult iar, Func2 endFunction, Action1 endAction, Task1 promise, Boolean requiresSynchronization)
--- End of stack trace from previous location ---
at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.ReceiveMessagesAsyncInternal(Int32 maxMessages, Nullable`1 maxWaitTime, TimeSpan timeout, CancellationToken cancellationToken) in ...\azure-sdk-for-net\sdk\servicebus\Azure.Messaging.ServiceBus\src\Amqp\AmqpReceiver.cs:line 375

and subsequent in ServiceBusSessionProcessor.ProcessErrorAsync handler:

Azure.Messaging.ServiceBus.ServiceBusException: The session lock has expired on the MessageSession. Accept a new MessageSession. TrackingId:, SystemTracker:...
(SessionLockLost). For troubleshooting information, see https://aka.ms/azsdk/net/servicebus/exceptions/troubleshoot.
at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.ThrowIfSessionLockLost()
at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.ReceiveMessagesAsyncInternal(Int32 maxMessages, Nullable1 maxWaitTime, TimeSpan timeout, CancellationToken cancellationToken) at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.<>c.<<ReceiveMessagesAsync>b__44_0>d.MoveNext() --- End of stack trace from previous location --- at Azure.Messaging.ServiceBus.ServiceBusRetryPolicy.RunOperation[T1,TResult](Func4 operation, T1 t1, TransportConnectionScope scope, CancellationToken cancellationToken, Boolean logTimeoutRetriesAsVerbose)
at Azure.Messaging.ServiceBus.ServiceBusRetryPolicy.RunOperation[T1,TResult](Func4 operation, T1 t1, TransportConnectionScope scope, CancellationToken cancellationToken, Boolean logTimeoutRetriesAsVerbose) at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.ReceiveMessagesAsync(Int32 maxMessages, Nullable1 maxWaitTime, CancellationToken cancellationToken)
at Azure.Messaging.ServiceBus.ServiceBusReceiver.ReceiveMessagesAsync(Int32 maxMessages, Nullable`1 maxWaitTime, Boolean isProcessor, CancellationToken cancellationToken)
at Azure.Messaging.ServiceBus.SessionReceiverManager.ReceiveAndProcessMessagesAsync(CancellationToken processorCancellationToken)

Expected behavior

In Azure.Messaging.ServiceBus 7.17.0 without the DrainAsyc there's no exception

Actual behavior

await link.DrainAsyc(cancellationToken).ConfigureAwait(false);

causing:

System.TimeoutException: The operation did not complete within the allocated time 00:01:00 for object drain.
at Microsoft.Azure.Amqp.ExceptionDispatcher.Throw(Exception exception)
at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result)
at Microsoft.Azure.Amqp.ReceivingAmqpLink.DrainAsyncResult.End(IAsyncResult result)
at Microsoft.Azure.Amqp.ReceivingAmqpLink.<>c.b__35_1(IAsyncResult r)
at System.Threading.Tasks.TaskFactory1.FromAsyncCoreLogic(IAsyncResult iar, Func2 endFunction, Action1 endAction, Task1 promise, Boolean requiresSynchronization)
--- End of stack trace from previous location ---
at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.ReceiveMessagesAsyncInternal(Int32 maxMessages, Nullable`1 maxWaitTime, TimeSpan timeout, CancellationToken cancellationToken) in ...\azure-sdk-for-net\sdk\servicebus\Azure.Messaging.ServiceBus\src\Amqp\AmqpReceiver.cs:line 375

and subsequent in ServiceBusSessionProcessor.ProcessErrorAsync handler:

Azure.Messaging.ServiceBus.ServiceBusException: The session lock has expired on the MessageSession. Accept a new MessageSession. TrackingId:, SystemTracker:...
(SessionLockLost). For troubleshooting information, see https://aka.ms/azsdk/net/servicebus/exceptions/troubleshoot.
at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.ThrowIfSessionLockLost()
at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.ReceiveMessagesAsyncInternal(Int32 maxMessages, Nullable1 maxWaitTime, TimeSpan timeout, CancellationToken cancellationToken) at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.<>c.<<ReceiveMessagesAsync>b__44_0>d.MoveNext() --- End of stack trace from previous location --- at Azure.Messaging.ServiceBus.ServiceBusRetryPolicy.RunOperation[T1,TResult](Func4 operation, T1 t1, TransportConnectionScope scope, CancellationToken cancellationToken, Boolean logTimeoutRetriesAsVerbose)
at Azure.Messaging.ServiceBus.ServiceBusRetryPolicy.RunOperation[T1,TResult](Func4 operation, T1 t1, TransportConnectionScope scope, CancellationToken cancellationToken, Boolean logTimeoutRetriesAsVerbose) at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.ReceiveMessagesAsync(Int32 maxMessages, Nullable1 maxWaitTime, CancellationToken cancellationToken)
at Azure.Messaging.ServiceBus.ServiceBusReceiver.ReceiveMessagesAsync(Int32 maxMessages, Nullable`1 maxWaitTime, Boolean isProcessor, CancellationToken cancellationToken)
at Azure.Messaging.ServiceBus.SessionReceiverManager.ReceiveAndProcessMessagesAsync(CancellationToken processorCancellationToken)

Reproduction Steps

using the CreateSessionProcessor and ProcessMessageAsync of ServiceBusClient

Environment

.Net Core 8.0, Windows 11
@github-actions github-actions bot added Client This issue points to a problem in the data-plane of the library. customer-reported Issues that are reported by GitHub users external to the Azure organization. needs-team-triage This issue needs the team to triage. question The issue doesn't require a change to the product in order to be resolved. Most issues start as that Service Bus labels Feb 7, 2024
@Yello001
Copy link
Author

Yello001 commented Feb 7, 2024

#40457 seems to introduce the problem
undo changes #41826 fixed the issue

@jsquire jsquire self-assigned this Feb 7, 2024
@jsquire
Copy link
Member

jsquire commented Feb 7, 2024

Hi @Yello001. Thank you for reaching out and we regret that you're experiencing difficulties. The timeouts that you're experiencing are not something that we're able to reproduce in our test suite nor that other developers have reported.

Could you help us better understand your scenario? It would be helpful to see how you're creating and configuring the processor and to understand how sessions are used for messages. We would appreciate if you could capture a 5-minute slice of Azure SDK logs around the timeout behavior, so that we can understand what the clients are seeing. Any other context that would help us reproduce what you're seeing would also be greatly appreciated.

@jsquire jsquire added needs-author-feedback More information is needed from author to address the issue. and removed needs-team-triage This issue needs the team to triage. labels Feb 7, 2024
@github-actions GitHub Actions
Copy link

github-actions bot commented Feb 7, 2024

Hi @Yello001. Thank you for opening this issue and giving us the opportunity to assist. To help our team better understand your issue and the details of your scenario please provide a response to the question asked above or the information requested above. This will help us more accurately address your issue.

@JoshLove-msft
Copy link
Member

The session processor will no longer drain as of #41834

@Yello001
Copy link
Author

Yello001 commented Feb 8, 2024

hello, yeah sure,
basically building up a Request/Response pattern over servicebus, with ServiceBusSender from ServiceBusClient.CreateSender and unique id to send

new ServiceBusMessage(messagePayload) { ReplyToSessionId = _sessionId }

and ServiceBusClient.CreateSessionProcessor with this options to receive

var options = new ServiceBusSessionProcessorOptions
                    {
                        PrefetchCount = 2, 
                        ReceiveMode = ServiceBusReceiveMode.ReceiveAndDelete
                    };
options.SessionIds.Add(_sessionId);

first messeges get response as expected, and after a couple minutes the processing blocks and throws exception afterwards.

the logs from start till exception

[Verbose] Azure-Messaging-ServiceBus: Creating a ServiceBusClient (Namespace: '<1>.servicebus.windows.net', Entity name: ''
[Verbose] Azure-Messaging-ServiceBus: A ServiceBusClient has been created (Identifier '<1>.servicebus.windows.net-<5>').
[Verbose] Azure-Messaging-ServiceBus: Creating a ServiceBusSender (Namespace: '<1>.servicebus.windows.net', Entity name: '<2>'
[Verbose] Azure-Messaging-ServiceBus: A ServiceBusSender has been created (Identifier '<2>-<identifier_link_1>').
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: StartProcessingAsync start.
[Verbose] Azure-Messaging-ServiceBus: Creating a ServiceBusSessionReceiver (Namespace: '<1>.servicebus.windows.net', Entity name: '<3>'
[Informational] Azure-Messaging-ServiceBus: Creating receive link for Identifier: <3>-<identifier_link_2>.
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: StartProcessingAsync done.
[Informational] Azure-Messaging-ServiceBus: <2>-<identifier_link_1>: SendAsync start. MessageCount = 1
[Informational] Azure-Messaging-ServiceBus: Creating send link for Identifier: <2>-<identifier_link_1>.
[Verbose] Azure-Messaging-ServiceBus: <3>-<identifier_link_2>: Requesting authorization to amqps://<1>.servicebus.windows.net/<3>
[Verbose] Azure-Messaging-ServiceBus: <2>-<identifier_link_1>: Requesting authorization to amqps://<1>.servicebus.windows.net/<2>
[Verbose] Azure-Messaging-ServiceBus: <2>-<identifier_link_1>: Authorization to amqps://<1>.servicebus.windows.net/<2> complete. Expiration time: 02/08/2024 09:04:11
[Verbose] Azure-Messaging-ServiceBus: <3>-<identifier_link_2>: Authorization to amqps://<1>.servicebus.windows.net/<3> complete. Expiration time: 02/08/2024 09:04:11
[Informational] Azure-Messaging-ServiceBus: Receive link created for Identifier: <3>-<identifier_link_2>. Session Id: <session_id>
[Verbose] Azure-Messaging-ServiceBus: A ServiceBusSessionReceiver has been created (Identifier '<3>-<identifier_link_2>').
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: Processor RenewSessionLock start. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: ReceiveBatchAsync start. MessageCount = 1
[Informational] Azure-Messaging-ServiceBus: Send link created for Identifier: <2>-<identifier_link_1>.
[Informational] Azure-Messaging-ServiceBus: <2>-<identifier_link_1>: SendAsync done.
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: ReceiveBatchAsync done. Received '1' messages. LockTokens = <LockToken>00000000-0000-0000-0000-000000000000</LockToken>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: User message handler start: Message: SequenceNumber: 1138054, LockToken: 00000000-0000-0000-0000-000000000000
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: User message handler complete: Message: SequenceNumber: 1138054, LockToken: 00000000-0000-0000-0000-000000000000
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: ReceiveBatchAsync start. MessageCount = 1
[Informational] Azure-Messaging-ServiceBus: <2>-<identifier_link_1>: SendAsync start. MessageCount = 1
[Informational] Azure-Messaging-ServiceBus: <2>-<identifier_link_1>: SendAsync done.
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: ReceiveBatchAsync done. Received '1' messages. LockTokens = <LockToken>00000000-0000-0000-0000-000000000000</LockToken>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: User message handler start: Message: SequenceNumber: 1138055, LockToken: 00000000-0000-0000-0000-000000000000
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: User message handler complete: Message: SequenceNumber: 1138055, LockToken: 00000000-0000-0000-0000-000000000000
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: ReceiveBatchAsync start. MessageCount = 1
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: RenewSessionLockAsync start. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: Creating management link for Identifier: <3>-<identifier_link_2>.
[Verbose] Azure-Messaging-ServiceBus: <3>-<identifier_link_2>: Requesting authorization to amqps://<1>.servicebus.windows.net/
[Verbose] Azure-Messaging-ServiceBus: <3>-<identifier_link_2>: Authorization to amqps://<1>.servicebus.windows.net/ complete. Expiration time: 02/08/2024 09:04:11
[Informational] Azure-Messaging-ServiceBus: Management link created for Identifier: <3>-<identifier_link_2>.
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: RenewSessionLockAsync done. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: Processor RenewSessionLock complete. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: Processor RenewSessionLock start. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: <2>-<identifier_link_1>: SendAsync start. MessageCount = 1
[Informational] Azure-Messaging-ServiceBus: <2>-<identifier_link_1>: SendAsync done.
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: ReceiveBatchAsync done. Received '1' messages. LockTokens = <LockToken>00000000-0000-0000-0000-000000000000</LockToken>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: User message handler start: Message: SequenceNumber: 1138056, LockToken: 00000000-0000-0000-0000-000000000000
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: User message handler complete: Message: SequenceNumber: 1138056, LockToken: 00000000-0000-0000-0000-000000000000
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: ReceiveBatchAsync start. MessageCount = 1
[Informational] Azure-Messaging-ServiceBus: <2>-<identifier_link_1>: SendAsync start. MessageCount = 1
[Informational] Azure-Messaging-ServiceBus: <2>-<identifier_link_1>: SendAsync done.
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: ReceiveBatchAsync done. Received '1' messages. LockTokens = <LockToken>00000000-0000-0000-0000-000000000000</LockToken>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: User message handler start: Message: SequenceNumber: 1138057, LockToken: 00000000-0000-0000-0000-000000000000
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: User message handler complete: Message: SequenceNumber: 1138057, LockToken: 00000000-0000-0000-0000-000000000000
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: ReceiveBatchAsync start. MessageCount = 1
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: RenewSessionLockAsync start. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: RenewSessionLockAsync done. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: Processor RenewSessionLock complete. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: Processor RenewSessionLock start. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: ReceiveBatchAsync done. Received '0' messages. LockTokens = 
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: ReceiveBatchAsync start. MessageCount = 1
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: RenewSessionLockAsync start. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: RenewSessionLockAsync done. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: Processor RenewSessionLock complete. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: Processor RenewSessionLock start. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: RenewSessionLockAsync start. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: RenewSessionLockAsync done. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: Processor RenewSessionLock complete. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: Processor RenewSessionLock start. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: ReceiveBatchAsync done. Received '0' messages. LockTokens = 
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: ReceiveBatchAsync start. MessageCount = 1
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: RenewSessionLockAsync start. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: RenewSessionLockAsync done. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: Processor RenewSessionLock complete. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: Processor RenewSessionLock start. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: ReceiveBatchAsync done. Received '0' messages. LockTokens = 
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: ReceiveBatchAsync start. MessageCount = 1
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: RenewSessionLockAsync start. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: RenewSessionLockAsync done. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: Processor RenewSessionLock complete. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: Processor RenewSessionLock start. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: ReceiveBatchAsync done. Received '0' messages. LockTokens = 
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: ReceiveBatchAsync start. MessageCount = 1
[Informational] Azure-Messaging-ServiceBus: <2>-<identifier_link_1>: SendAsync start. MessageCount = 1
[Informational] Azure-Messaging-ServiceBus: <2>-<identifier_link_1>: SendAsync done.
[Informational] Azure-Messaging-ServiceBus: Management Link Closed. Identifier: <3>-<identifier_link_2>, linkException: .
[Informational] Azure-Messaging-ServiceBus: Receive Link Closed. Identifier: <3>-<identifier_link_2>, SessionId: <session_id>, linkException: .
[Warning] Azure-Messaging-ServiceBus: RunOperation encountered an exception and will retry. Exception: Azure.Messaging.ServiceBus.ServiceBusException: The operation did not complete within the allocated time 00:01:00 for object drain. (ServiceTimeout). For troubleshooting information, see https://aka.ms/azsdk/net/servicebus/exceptions/troubleshoot.
 ---> System.TimeoutException: The operation did not complete within the allocated time 00:01:00 for object drain.
   at Microsoft.Azure.Amqp.ExceptionDispatcher.Throw(Exception exception)
   at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result)
   at Microsoft.Azure.Amqp.ReceivingAmqpLink.DrainAsyncResult.End(IAsyncResult result)
   at Microsoft.Azure.Amqp.ReceivingAmqpLink.<>c.<DrainAsyc>b__35_1(IAsyncResult r)
   at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
--- End of stack trace from previous location ---
   at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.ReceiveMessagesAsyncInternal(Int32 maxMessages, Nullable`1 maxWaitTime, TimeSpan timeout, CancellationToken cancellationToken) in ...\azure-sdk-for-net\sdk\servicebus\Azure.Messaging.ServiceBus\src\Amqp\AmqpReceiver.cs:line 375
   --- End of inner exception stack trace ---
   at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.ReceiveMessagesAsyncInternal(Int32 maxMessages, Nullable`1 maxWaitTime, TimeSpan timeout, CancellationToken cancellationToken) in ...\azure-sdk-for-net\sdk\servicebus\Azure.Messaging.ServiceBus\src\Amqp\AmqpReceiver.cs:line 403
   at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.<>c.<<ReceiveMessagesAsync>b__44_0>d.MoveNext() in ...\azure-sdk-for-net\sdk\servicebus\Azure.Messaging.ServiceBus\src\Amqp\AmqpReceiver.cs:line 322
--- End of stack trace from previous location ---
   at Azure.Messaging.ServiceBus.ServiceBusRetryPolicy.RunOperation[T1,TResult](Func`4 operation, T1 t1, TransportConnectionScope scope, CancellationToken cancellationToken, Boolean logTimeoutRetriesAsVerbose) in ...\azure-sdk-for-net\sdk\servicebus\Azure.Messaging.ServiceBus\src\Primitives\ServiceBusRetryPolicy.cs:line 153
[Error] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: ReceiveBatchAsync Exception: Azure.Messaging.ServiceBus.ServiceBusException: The session lock has expired on the MessageSession. Accept a new MessageSession. Tr
ackingId:<tracking_id>_G17_B33, SystemTracker:G17:119320424:amqps://<1>.servicebus.windows.net/-e517c57a;0:6:8:source(address:/<3>,filter:[com.microsoft:session-filter:<session_id>]), Timestamp:2024-02-08T08:39:46 (SessionLockLost). For troubleshooting information, see https://aka.ms/azsdk/net/servicebus/exceptions/troubleshoot.
   at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.ThrowIfSessionLockLost() in ...\azure-sdk-for-net\sdk\servicebus\Azure.Messaging.ServiceBus\src\Amqp\AmqpReceiver.cs:line 1473
   at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.ReceiveMessagesAsyncInternal(Int32 maxMessages, Nullable`1 maxWaitTime, TimeSpan timeout, CancellationToken cancellationToken) in ...\azure-sdk-for-net\sdk\servicebus\Azure.Messaging.ServiceBus\src\Amqp\AmqpReceiver.cs:line 352
   at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.<>c.<<ReceiveMessagesAsync>b__44_0>d.MoveNext() in ...\azure-sdk-for-net\sdk\servicebus\Azure.Messaging.ServiceBus\src\Amqp\AmqpReceiver.cs:line 322
--- End of stack trace from previous location ---
   at Azure.Messaging.ServiceBus.ServiceBusRetryPolicy.RunOperation[T1,TResult](Func`4 operation, T1 t1, TransportConnectionScope scope, CancellationToken cancellationToken, Boolean logTimeoutRetriesAsVerbose) in ...\azure-sdk-for-net\sdk\servicebus\Azure.Messaging.ServiceBus\src\Primitives\ServiceBusRetryPolicy.cs:line 153
   at Azure.Messaging.ServiceBus.ServiceBusRetryPolicy.RunOperation[T1,TResult](Func`4 operation, T1 t1, TransportConnectionScope scope, CancellationToken cancellationToken, Boolean logTimeoutRetriesAsVerbose) in ...\azure-sdk-for-net\sdk\servicebus\Azure.Messaging.ServiceBus\src\Primitives\ServiceBusRetryPolicy.cs:line 185
   at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.ReceiveMessagesAsync(Int32 maxMessages, Nullable`1 maxWaitTime, CancellationToken cancellationToken) in ...\azure-sdk-for-net\sdk\servicebus\Azure.Messaging.ServiceBus\src\Amqp\AmqpReceiver.cs:line 319
   at Azure.Messaging.ServiceBus.ServiceBusReceiver.ReceiveMessagesAsync(Int32 maxMessages, Nullable`1 maxWaitTime, Boolean isProcessor, CancellationToken cancellationToken) in ...\azure-sdk-for-net\sdk\servicebus\Azure.Messaging.ServiceBus\src\Receiver\ServiceBusReceiver.cs:line 330.
fail: RpcClient[0]
      Error while processing Service Bus RPC response
      Azure.Messaging.ServiceBus.ServiceBusException: The session lock has expired on the MessageSession. Accept a new MessageSession. TrackingId:<tracking_id>_G17_B33, SystemTracker:G17:119320424:amqps://<1>.servicebus.windows.net/-e517c57a;0:6:8:source(address:/<3>,filter:[com.microsoft:session-filter:<session_id>]), Timestamp:2024-02-08T08:39:46 (SessionLockLost). For troubleshooting information, see https://aka.ms/azsdk/net/servicebus/exceptions/troubleshoot.
         at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.ThrowIfSessionLockLost() in ...\azure-sdk-for-net\sdk\servicebus\Azure.Messaging.ServiceBus\src\Amqp\AmqpReceiver.cs:line 1473
         at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.ReceiveMessagesAsyncInternal(Int32 maxMessages, Nullable`1 maxWaitTime, TimeSpan timeout, CancellationToken cancellationToken) in ...\azure-sdk-for-net\sdk\servicebus\Azure.Messaging.ServiceBus\src\Amqp\AmqpReceiver.cs:line 352
         at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.<>c.<<ReceiveMessagesAsync>b__44_0>d.MoveNext() in ...\azure-sdk-for-net\sdk\servicebus\Azure.Messaging.ServiceBus\src\Amqp\AmqpReceiver.cs:line 322
      --- End of stack trace from previous location ---
         at Azure.Messaging.ServiceBus.ServiceBusRetryPolicy.RunOperation[T1,TResult](Func`4 operation, T1 t1, TransportConnectionScope scope, CancellationToken cancellationToken, Boolean logTimeoutRetriesAsVerbose) in ...\azure-sdk-for-net\sdk\servicebus\Azure.Messaging.ServiceBus\src\Primitives\ServiceBusRetryPolicy.cs:line 153
         at Azure.Messaging.ServiceBus.ServiceBusRetryPolicy.RunOperation[T1,TResult](Func`4 operation, T1 t1, TransportConnectionScope scope, CancellationToken cancellationToken, Boolean logTimeoutRetriesAsVerbose) in ...\azure-sdk-for-net\sdk\servicebus\Azure.Messaging.ServiceBus\src\Primitives\ServiceBusRetryPolicy.cs:line 185
         at Azure.Messaging.ServiceBus.Amqp.AmqpReceiver.ReceiveMessagesAsync(Int32 maxMessages, Nullable`1 maxWaitTime, CancellationToken cancellationToken) in ...\azure-sdk-for-net\sdk\servicebus\Azure.Messaging.ServiceBus\src\Amqp\AmqpReceiver.cs:line 319
         at Azure.Messaging.ServiceBus.ServiceBusReceiver.ReceiveMessagesAsync(Int32 maxMessages, Nullable`1 maxWaitTime, Boolean isProcessor, CancellationToken cancellationToken) in ...\azure-sdk-for-net\sdk\servicebus\Azure.Messaging.ServiceBus\src\Receiver\ServiceBusReceiver.cs:line 330       
         at Azure.Messaging.ServiceBus.SessionReceiverManager.ReceiveAndProcessMessagesAsync(CancellationToken processorCancellationToken) in ...\azure-sdk-for-net\sdk\servicebus\Azure.Messaging.ServiceBus\src\Processor\SessionReceiverManager.cs:line 308
[Verbose] Azure-Messaging-ServiceBus: Closing a ServiceBusSessionReceiver (Identifier '<3>-<4>-S<session_id>').
[Verbose] Azure-Messaging-ServiceBus: A ServiceBusSessionReceiver has been closed (Identifier '<3>-<4>-S<session_id>').
[Verbose] Azure-Messaging-ServiceBus: Creating a ServiceBusSessionReceiver (Namespace: '<1>.servicebus.windows.net', Entity name: '<3>'
[Informational] Azure-Messaging-ServiceBus: Creating receive link for Identifier: <3>-<5>.
[Verbose] Azure-Messaging-ServiceBus: <3>-<5>: Requesting authorization to amqps://<1>.servicebus.windows.net/<3>
[Verbose] Azure-Messaging-ServiceBus: <3>-<5>: Authorization to amqps://<1>.servicebus.windows.net/<3> complete. Expiration time: 02/08/2024 09:04:11
[Informational] Azure-Messaging-ServiceBus: Receive link created for Identifier: <3>-<5>. Session Id: <session_id>
[Verbose] Azure-Messaging-ServiceBus: A ServiceBusSessionReceiver has been created (Identifier '<3>-<5>').
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: Processor RenewSessionLock start. SessionId = <session_id>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: ReceiveBatchAsync start. MessageCount = 1
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: ReceiveBatchAsync done. Received '1' messages. LockTokens = <LockToken>00000000-0000-0000-0000-000000000000</LockToken>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: User message handler start: Message: SequenceNumber: 1138058, LockToken: 00000000-0000-0000-0000-000000000000
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: User message handler complete: Message: SequenceNumber: 1138058, LockToken: 00000000-0000-0000-0000-000000000000
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: ReceiveBatchAsync start. MessageCount = 1
[Informational] Azure-Messaging-ServiceBus: <2>-<identifier_link_1>: SendAsync start. MessageCount = 1
[Informational] Azure-Messaging-ServiceBus: <2>-<identifier_link_1>: SendAsync done.
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: ReceiveBatchAsync done. Received '1' messages. LockTokens = <LockToken>00000000-0000-0000-0000-000000000000</LockToken>
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: User message handler start: Message: SequenceNumber: 1138059, LockToken: 00000000-0000-0000-0000-000000000000
[Informational] Azure-Messaging-ServiceBus: <3>-<4>: User message handler complete: Message: SequenceNumber: 1138059, LockToken: 00000000-0000-0000-0000-000000000000
[Informational] Azure-Messaging-ServiceBus: <3>-<4>-S<session_id>: ReceiveBatchAsync start. MessageCount = 1

@github-actions github-actions bot added needs-team-attention This issue needs attention from Azure service team or SDK team and removed needs-author-feedback More information is needed from author to address the issue. labels Feb 8, 2024
@Yello001
Copy link
Author

Yello001 commented Feb 8, 2024

Tested with #41834 from @JoshLove-msft
-> seems to solve the issue, no exception afterwards 👍

@jsquire
Copy link
Member

jsquire commented Feb 8, 2024

Thanks, @Yello001. That removes the drain from this scenario, but the timeout is still unusual and I'd to understand the cause of that.
@JoshLove-msft: Do you think that the "success" here is the messages in prefetch being dispatched and then the attempt to acquire the session lock the next time around fails?

@JoshLove-msft JoshLove-msft mentioned this issue Feb 13, 2024
Merged
@github-actions github-actions bot locked and limited conversation to collaborators May 14, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@jsquire jsquire

@JoshLove-msft JoshLove-msft

Labels
Client This issue points to a problem in the data-plane of the library. customer-reported Issues that are reported by GitHub users external to the Azure organization. needs-team-attention This issue needs attention from Azure service team or SDK team question The issue doesn't require a change to the product in order to be resolved. Most issues start as that Service Bus
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Fix for drain when prefetch is enabled JoshLove-msft/azure-sdk-for-net
3 participants
@jsquire @Yello001 @JoshLove-msft