Don't log receive cancellation as an error (#34399)

* Don't log receive cancellation as an error * Fix failing test
Azure · Feb 21, 2023 · 109446e · 109446e
1 parent 4c329d7
commit 109446e
Show file tree

Hide file tree

Showing 4 changed files with 48 additions and 4 deletions.
diff --git a/sdk/servicebus/Azure.Messaging.ServiceBus/src/Diagnostics/ServiceBusEventSource.cs b/sdk/servicebus/Azure.Messaging.ServiceBus/src/Diagnostics/ServiceBusEventSource.cs
@@ -195,6 +195,7 @@ protected ServiceBusEventSource() : base(EventSourceName)
         internal const int ProcessorStoppingCancellationWarningEvent = 113;
 
         internal const int RunOperationExceptionVerboseEvent = 114;
+        internal const int ReceiveMessageCanceledEvent = 115;
 
         #endregion
         // add new event numbers here incrementing from previous
@@ -297,6 +298,15 @@ public virtual void ReceiveMessageException(
             }
         }
 
+        [Event(ReceiveMessageCanceledEvent, Level = EventLevel.Verbose, Message = "A receive operation was cancelled. (Identifier '{0}'). Error Message: '{1}'")]
+        public void ReceiveMessageCanceled(string identifier, string exception)
+        {
+            if (IsEnabled())
+            {
+                WriteEvent(ReceiveMessageCanceledEvent, identifier, exception);
+            }
+        }
+
         [NonEvent]
         public virtual void ReceiveDeferredMessageStart(string identifier, long[] sequenceNumbers)
         {

diff --git a/sdk/servicebus/Azure.Messaging.ServiceBus/src/Receiver/ServiceBusReceiver.cs b/sdk/servicebus/Azure.Messaging.ServiceBus/src/Receiver/ServiceBusReceiver.cs
@@ -326,10 +326,13 @@ internal async Task<IReadOnlyList<ServiceBusReceivedMessage>> ReceiveMessagesAsy
                     cancellationToken).ConfigureAwait(false);
             }
             catch (OperationCanceledException ex)
-                when (isProcessor && cancellationToken.IsCancellationRequested)
+                when (cancellationToken.IsCancellationRequested)
             {
                 scope.BackdateStart(startTime);
-                Logger.ProcessorStoppingReceiveCanceled(Identifier, ex.ToString());
+                if (isProcessor)
+                    Logger.ProcessorStoppingReceiveCanceled(Identifier, ex.ToString());
+                else
+                    Logger.ReceiveMessageCanceled(Identifier, ex.ToString());
                 scope.Failed(ex);
                 throw;
             }

diff --git a/sdk/servicebus/Azure.Messaging.ServiceBus/tests/Diagnostics/EventSourceLiveTests.cs b/sdk/servicebus/Azure.Messaging.ServiceBus/tests/Diagnostics/EventSourceLiveTests.cs
@@ -628,5 +628,35 @@ public async Task ClosingReceiveLinkDoesNotCloseSessionWithCrossEntityTransactio
                 Assert.False(_listener.EventsById(ServiceBusEventSource.SendLinkClosedEvent).Any(e => e.Payload.Contains(sender.Identifier)));
             }
         }
+
+        [Test]
+        public async Task CancellingReceiveLogsVerboseCancellationEvent()
+        {
+            await using (var scope = await ServiceBusScope.CreateWithQueue(enablePartitioning: false, enableSession: false))
+            {
+                await using var client = new ServiceBusClient(TestEnvironment.ServiceBusConnectionString);
+                var receiver = client.CreateReceiver(scope.QueueName);
+
+                var cts = new CancellationTokenSource();
+                cts.CancelAfter(TimeSpan.FromSeconds(1));
+
+                await AsyncAssert.ThrowsAsync<OperationCanceledException>(
+                    async () => await receiver.ReceiveMessageAsync(TimeSpan.FromSeconds(5), cts.Token));
+
+                _listener.SingleEventById(ServiceBusEventSource.ReceiveMessageCanceledEvent, e => e.Payload.Contains(receiver.Identifier) && e.Level == EventLevel.Verbose);
+            }
+        }
+
+        [Test]
+        public async Task ReceiveFromNonExistentQueueLogsErrorEvent()
+        {
+            await using var client = new ServiceBusClient(TestEnvironment.ServiceBusConnectionString);
+            var receiver = client.CreateReceiver("nonexistentqueue");
+
+            await AsyncAssert.ThrowsAsync<ServiceBusException>(
+                async () => await receiver.ReceiveMessageAsync());
+
+            _listener.SingleEventById(ServiceBusEventSource.ReceiveMessageExceptionEvent, e => e.Payload.Contains(receiver.Identifier) && e.Level == EventLevel.Error);
+        }
     }
 }
diff --git a/sdk/servicebus/Azure.Messaging.ServiceBus/tests/Sender/ServiceBusMessageBatchLiveTests.cs b/sdk/servicebus/Azure.Messaging.ServiceBus/tests/Sender/ServiceBusMessageBatchLiveTests.cs
@@ -54,8 +54,9 @@ async Task AddAndSendMessages()
                         if (batch.Count < 4500)
                         {
                             var diff = batch.MaxSizeInBytes - batch.SizeInBytes;
-                            // the difference in size from the max allowable size should be less than the size of 1 message
-                            Assert.IsTrue(diff < 220, diff.ToString());
+                            // the difference in size from the max allowable size should be less than the size of a single
+                            // instrumented message
+                            Assert.IsTrue(diff < 250, diff.ToString());
                         }
                         Assert.Greater(batch.Count, 0);
                         await sender.SendMessagesAsync(batch);