Skip to content

Commit cb240f3

Browse files
JoshLove-msftJoshLove-msft
authored
Include locktoken in more logs (Azure#22849)
1 parent 5e6bcc0 commit cb240f3

File tree

6 files changed

+97
-79
lines changed

6 files changed

+97
-79
lines changed

‎sdk/servicebus/Azure.Messaging.ServiceBus/src/Diagnostics/ServiceBusEventSource.cs‎

Lines changed: 52 additions & 45 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@
44
using System;
55
using System.Collections.Generic;
66
using System.Diagnostics.Tracing;
7+
using System.Linq;
78
using System.Reflection;
89
using System.Threading.Tasks;
910
using Azure.Core.Diagnostics;
@@ -171,10 +172,6 @@ protected ServiceBusEventSource() : base(EventSourceName)
171172
internal const int ProcessorErrorHandlerThrewExceptionEvent = 94;
172173
internal const int ScheduleTaskFailedEvent = 95;
173174

174-
internal const int PluginStartEvent = 96;
175-
internal const int PluginCompleteEvent = 97;
176-
internal const int PluginExceptionEvent = 98;
177-
178175
internal const int MaxMessagesExceedsPrefetchEvent = 99;
179176
internal const int SendLinkClosedEvent = 100;
180177
internal const int ManagementLinkClosedEvent = 101;
@@ -262,14 +259,26 @@ public virtual void ReceiveMessageStart(string identifier, int messageCount)
262259
}
263260
}
264261

265-
[Event(ReceiveMessageCompleteEvent, Level = EventLevel.Informational, Message = "{0}: ReceiveBatchAsync done. Received '{1}' messages")]
262+
[NonEvent]
266263
public virtual void ReceiveMessageComplete(
267264
string identifier,
268-
int messageCount)
265+
IReadOnlyList<ServiceBusReceivedMessage> messages)
269266
{
270267
if (IsEnabled())
271268
{
272-
WriteEvent(ReceiveMessageCompleteEvent, identifier, messageCount);
269+
ReceiveMessageCompleteCore(identifier, messages.Count, StringUtility.GetFormattedLockTokens(messages.Select(m => m.LockTokenGuid)));
270+
}
271+
}
272+
273+
[Event(ReceiveMessageCompleteEvent, Level = EventLevel.Informational, Message = "{0}: ReceiveBatchAsync done. Received '{1}' messages. LockTokens = {2}")]
274+
private void ReceiveMessageCompleteCore(
275+
string identifier,
276+
int messageCount,
277+
string lockTokens)
278+
{
279+
if (IsEnabled())
280+
{
281+
WriteEvent(ReceiveMessageCompleteEvent, identifier, messageCount, lockTokens);
273282
}
274283
}
275284

@@ -809,30 +818,57 @@ public void ProcessorErrorHandlerThrewException(string exception)
809818
}
810819
}
811820

812-
[Event(ProcessorMessageHandlerStartEvent, Level = EventLevel.Informational, Message = "{0}: User message handler start: Message: SequenceNumber: {1}")]
813-
public void ProcessorMessageHandlerStart(string identifier, long sequenceNumber)
821+
[NonEvent]
822+
public void ProcessorMessageHandlerStart(string identifier, long sequenceNumber, Guid lockToken)
814823
{
815824
if (IsEnabled())
816825
{
817-
WriteEvent(ProcessorMessageHandlerStartEvent, identifier, sequenceNumber);
826+
ProcessorMessageHandlerStartCore(identifier, sequenceNumber, lockToken.ToString());
818827
}
819828
}
820829

821-
[Event(ProcessorMessageHandlerCompleteEvent, Level = EventLevel.Informational, Message = "{0}: User message handler complete: Message: SequenceNumber: {1}")]
822-
public void ProcessorMessageHandlerComplete(string identifier, long sequenceNumber)
830+
[Event(ProcessorMessageHandlerStartEvent, Level = EventLevel.Informational, Message = "{0}: User message handler start: Message: SequenceNumber: {1}, LockToken: {2}")]
831+
private void ProcessorMessageHandlerStartCore(string identifier, long sequenceNumber, string lockToken)
823832
{
824833
if (IsEnabled())
825834
{
826-
WriteEvent(ProcessorMessageHandlerCompleteEvent, identifier, sequenceNumber);
835+
WriteEvent(ProcessorMessageHandlerStartEvent, identifier, sequenceNumber, lockToken);
827836
}
828837
}
829838

830-
[Event(ProcessorMessageHandlerExceptionEvent, Level = EventLevel.Error, Message = "{0}: User message handler complete: Message: SequenceNumber: {1}, Exception: {2}")]
831-
public void ProcessorMessageHandlerException(string identifier, long sequenceNumber, string exception)
839+
[NonEvent]
840+
public void ProcessorMessageHandlerComplete(string identifier, long sequenceNumber, Guid lockToken)
832841
{
833842
if (IsEnabled())
834843
{
835-
WriteEvent(ProcessorMessageHandlerExceptionEvent, identifier, sequenceNumber, exception);
844+
ProcessorMessageHandlerCompleteCore(identifier, sequenceNumber, lockToken.ToString());
845+
}
846+
}
847+
848+
[Event(ProcessorMessageHandlerCompleteEvent, Level = EventLevel.Informational, Message = "{0}: User message handler complete: Message: SequenceNumber: {1}, LockToken: {2}")]
849+
private void ProcessorMessageHandlerCompleteCore(string identifier, long sequenceNumber, string lockToken)
850+
{
851+
if (IsEnabled())
852+
{
853+
WriteEvent(ProcessorMessageHandlerCompleteEvent, identifier, sequenceNumber, lockToken);
854+
}
855+
}
856+
857+
[NonEvent]
858+
public void ProcessorMessageHandlerException(string identifier, long sequenceNumber, string exception, Guid lockToken)
859+
{
860+
if (IsEnabled())
861+
{
862+
ProcessorMessageHandlerExceptionCore(identifier, sequenceNumber, exception, lockToken.ToString());
863+
}
864+
}
865+
866+
[Event(ProcessorMessageHandlerExceptionEvent, Level = EventLevel.Error, Message = "{0}: User message handler complete: Message: SequenceNumber: {1}, Exception: {2}, LockToken: {3}")]
867+
private void ProcessorMessageHandlerExceptionCore(string identifier, long sequenceNumber, string exception, string lockToken)
868+
{
869+
if (IsEnabled())
870+
{
871+
WriteEvent(ProcessorMessageHandlerExceptionEvent, identifier, sequenceNumber, exception, lockToken);
836872
}
837873
}
838874

@@ -1501,35 +1537,6 @@ public void CreateControllerException(string connectionManager, string exception
15011537
}
15021538
#endregion
15031539

1504-
#region plugins
1505-
[Event(PluginStartEvent, Level = EventLevel.Verbose, Message = "User plugin {0} called on message {1}")]
1506-
public void PluginCallStarted(string pluginName, string messageId)
1507-
{
1508-
if (IsEnabled())
1509-
{
1510-
WriteEvent(PluginStartEvent, pluginName, messageId);
1511-
}
1512-
}
1513-
1514-
[Event(PluginCompleteEvent, Level = EventLevel.Verbose, Message = "User plugin {0} completed on message {1}")]
1515-
public void PluginCallCompleted(string pluginName, string messageId)
1516-
{
1517-
if (IsEnabled())
1518-
{
1519-
WriteEvent(PluginCompleteEvent, pluginName, messageId);
1520-
}
1521-
}
1522-
1523-
[Event(PluginExceptionEvent, Level = EventLevel.Error, Message = "Exception during {0} plugin execution. MessageId: {1}, Exception {2}")]
1524-
public void PluginCallException(string pluginName, string messageId, string exception)
1525-
{
1526-
if (IsEnabled())
1527-
{
1528-
WriteEvent(PluginExceptionEvent, pluginName, messageId, exception);
1529-
}
1530-
}
1531-
#endregion
1532-
15331540
#region misc
15341541
[NonEvent]
15351542
public void ScheduleTaskFailed(Func<Task> task, Exception exception)

‎sdk/servicebus/Azure.Messaging.ServiceBus/src/Primitives/StringUtility.cs‎

Lines changed: 3 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,7 @@
11
// Copyright (c) Microsoft Corporation. All rights reserved.
22
// Licensed under the MIT License.
33

4+
using System;
45
using System.Collections.Generic;
56
using System.Globalization;
67
using System.Text;
@@ -9,12 +10,12 @@ namespace Azure.Messaging.ServiceBus.Primitives
910
{
1011
internal static class StringUtility
1112
{
12-
public static string GetFormattedLockTokens(IEnumerable<string> lockTokens)
13+
public static string GetFormattedLockTokens(IEnumerable<Guid> lockTokens)
1314
{
1415
var lockTokenBuilder = new StringBuilder();
1516
foreach (var lockToken in lockTokens)
1617
{
17-
lockTokenBuilder.AppendFormat(CultureInfo.InvariantCulture, "<LockToken>{0}</LockToken>", lockToken);
18+
lockTokenBuilder.AppendFormat(CultureInfo.InvariantCulture, "<LockToken>{0}</LockToken>", lockToken.ToString());
1819
}
1920

2021
return lockTokenBuilder.ToString();
@@ -38,21 +39,5 @@ public static string FormatForUser(this string format, params object[] args)
3839
{
3940
return string.Format(CultureInfo.CurrentCulture, format, args);
4041
}
41-
42-
/// <summary>
43-
/// Formats a string+parameter using InvariantCulture. This overload avoids allocating an array when there's only one replacement parameter
44-
/// </summary>
45-
public static string FormatInvariant(this string format, object arg0)
46-
{
47-
return string.Format(CultureInfo.InvariantCulture, format, arg0);
48-
}
49-
50-
/// <summary>
51-
/// Formats a string+parameters using InvariantCulture.
52-
/// </summary>
53-
public static string FormatInvariant(this string format, params object[] args)
54-
{
55-
return string.Format(CultureInfo.InvariantCulture, format, args);
56-
}
5742
}
5843
}

‎sdk/servicebus/Azure.Messaging.ServiceBus/src/Processor/ReceiverManager.cs‎

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -158,13 +158,13 @@ private async Task ProcessOneMessage(
158158

159159
try
160160
{
161-
ServiceBusEventSource.Log.ProcessorMessageHandlerStart(Processor.Identifier, message.SequenceNumber);
161+
ServiceBusEventSource.Log.ProcessorMessageHandlerStart(Processor.Identifier, message.SequenceNumber, message.LockTokenGuid);
162162
await OnMessageHandler(message, cancellationToken).ConfigureAwait(false);
163-
ServiceBusEventSource.Log.ProcessorMessageHandlerComplete(Processor.Identifier, message.SequenceNumber);
163+
ServiceBusEventSource.Log.ProcessorMessageHandlerComplete(Processor.Identifier, message.SequenceNumber, message.LockTokenGuid);
164164
}
165165
catch (Exception ex)
166166
{
167-
ServiceBusEventSource.Log.ProcessorMessageHandlerException(Processor.Identifier, message.SequenceNumber, ex.ToString());
167+
ServiceBusEventSource.Log.ProcessorMessageHandlerException(Processor.Identifier, message.SequenceNumber, ex.ToString(), message.LockTokenGuid);
168168
throw;
169169
}
170170

‎sdk/servicebus/Azure.Messaging.ServiceBus/src/Receiver/ServiceBusReceiver.cs‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -299,7 +299,7 @@ internal async Task<IReadOnlyList<ServiceBusReceivedMessage>> ReceiveMessagesAsy
299299
throw;
300300
}
301301

302-
Logger.ReceiveMessageComplete(Identifier, messages.Count);
302+
Logger.ReceiveMessageComplete(Identifier, messages);
303303
scope.SetMessageData(messages);
304304

305305
return messages;

‎sdk/servicebus/Azure.Messaging.ServiceBus/tests/Diagnostics/EventSourceLiveTests.cs‎

Lines changed: 30 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -69,6 +69,7 @@ public async Task LogsEvents()
6969

7070
var messageEnum = messages.GetEnumerator();
7171
var remainingMessages = messageCount;
72+
List<string> lockTokens = new();
7273
while (remainingMessages > 0)
7374
{
7475
foreach (var item in await receiver.ReceiveMessagesAsync(remainingMessages))
@@ -77,6 +78,7 @@ public async Task LogsEvents()
7778
messageEnum.MoveNext();
7879
Assert.AreEqual(messageEnum.Current.MessageId, item.MessageId);
7980
Assert.AreEqual(item.DeliveryCount, 1);
81+
lockTokens.Add(item.LockToken);
8082
}
8183
}
8284
_listener.SingleEventById(ServiceBusEventSource.CreateReceiveLinkStartEvent, e => e.Payload.Contains(receiver.Identifier));
@@ -85,6 +87,22 @@ public async Task LogsEvents()
8587
_listener.SingleEventById(ServiceBusEventSource.CreateReceiveLinkCompleteEvent, e => e.Payload.Contains(receiver.Identifier));
8688
Assert.IsTrue(_listener.EventsById(ServiceBusEventSource.ReceiveMessageStartEvent).Any());
8789
Assert.IsTrue(_listener.EventsById(ServiceBusEventSource.ReceiveMessageCompleteEvent).Any());
90+
91+
var receiveCompleteEvents = _listener.EventsById(ServiceBusEventSource.ReceiveMessageCompleteEvent);
92+
foreach (string lockToken in lockTokens)
93+
{
94+
bool found = false;
95+
foreach (var evt in receiveCompleteEvents)
96+
{
97+
if (evt.Payload.Any(m => m.ToString().Contains(lockToken)))
98+
{
99+
found = true;
100+
break;
101+
}
102+
}
103+
Assert.IsTrue(found, $"Locktoken {lockToken} not found in event logs");
104+
}
105+
88106
Assert.AreEqual(0, remainingMessages);
89107
messageEnum.Reset();
90108

@@ -175,6 +193,7 @@ public async Task LogsSessionEvents()
175193

176194
var msg = await sessionReceiver.ReceiveMessageAsync();
177195
_listener.SingleEventById(ServiceBusEventSource.ReceiveMessageStartEvent, e => e.Payload.Contains(sessionReceiver.Identifier));
196+
_listener.SingleEventById(ServiceBusEventSource.ReceiveMessageCompleteEvent, e => e.Payload.Contains(sessionReceiver.Identifier) && e.Payload.Contains($"<LockToken>{msg.LockToken}</LockToken>"));
178197

179198
msg = await sessionReceiver.PeekMessageAsync();
180199
_listener.SingleEventById(ServiceBusEventSource.CreateManagementLinkStartEvent, e => e.Payload.Contains(sessionReceiver.Identifier));
@@ -235,9 +254,10 @@ public async Task LogsProcessorEvents()
235254
await sender.SendMessageAsync(GetMessage());
236255
await using var processor = client.CreateProcessor(scope.QueueName);
237256
var tcs = new TaskCompletionSource<bool>();
238-
257+
string lockToken = null;
239258
Task ProcessMessage(ProcessMessageEventArgs args)
240259
{
260+
lockToken = args.Message.LockToken;
241261
tcs.SetResult(true);
242262
return Task.CompletedTask;
243263
}
@@ -253,8 +273,15 @@ Task ExceptionHandler(ProcessErrorEventArgs args)
253273
await processor.StartProcessingAsync();
254274
await tcs.Task;
255275
await processor.StopProcessingAsync();
256-
_listener.SingleEventById(ServiceBusEventSource.ProcessorMessageHandlerStartEvent);
257-
_listener.SingleEventById(ServiceBusEventSource.ProcessorMessageHandlerCompleteEvent);
276+
_listener.SingleEventById(
277+
ServiceBusEventSource.ReceiveMessageCompleteEvent,
278+
e => e.Payload.Contains($"<LockToken>{lockToken}</LockToken>"));
279+
_listener.SingleEventById(
280+
ServiceBusEventSource.ProcessorMessageHandlerStartEvent,
281+
e => e.Payload.Contains(processor.Identifier) && e.Payload.Contains(lockToken));
282+
_listener.SingleEventById(
283+
ServiceBusEventSource.ProcessorMessageHandlerCompleteEvent,
284+
e => e.Payload.Contains(processor.Identifier) && e.Payload.Contains(lockToken));
258285
}
259286
}
260287

‎sdk/servicebus/Azure.Messaging.ServiceBus/tests/Diagnostics/EventSourceTests.cs‎

Lines changed: 8 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -307,15 +307,14 @@ public async Task ReceiveSingleMessageLogsEvents()
307307
var mockLogger = new Mock<ServiceBusEventSource>();
308308
var mockTransportReceiver = new Mock<TransportReceiver>();
309309
var mockConnection = GetMockConnection(mockTransportReceiver);
310-
310+
var received = (IReadOnlyList<ServiceBusReceivedMessage>)
311+
new List<ServiceBusReceivedMessage> { new() };
311312
mockTransportReceiver.Setup(
312313
transportReceiver => transportReceiver.ReceiveMessagesAsync(
313314
1,
314315
It.IsAny<TimeSpan?>(),
315316
It.IsAny<CancellationToken>()))
316-
.Returns(
317-
Task.FromResult((IReadOnlyList<ServiceBusReceivedMessage>)
318-
new List<ServiceBusReceivedMessage> { new ServiceBusReceivedMessage() }));
317+
.Returns(Task.FromResult(received));
319318
var receiver = new ServiceBusReceiver(
320319
mockConnection.Object,
321320
"queueName",
@@ -337,7 +336,7 @@ public async Task ReceiveSingleMessageLogsEvents()
337336
.Verify(
338337
log => log.ReceiveMessageComplete(
339338
receiver.Identifier,
340-
1),
339+
received),
341340
Times.Once);
342341
mockLogger
343342
.Verify(
@@ -355,16 +354,16 @@ public async Task ReceiveBatchOfMessagesLogsEvents()
355354
var maxMessages = 4;
356355
var mockTransportReceiver = new Mock<TransportReceiver>();
357356
var mockConnection = GetMockConnection(mockTransportReceiver);
357+
var received = (IReadOnlyList<ServiceBusReceivedMessage>)
358+
new List<ServiceBusReceivedMessage> { new() };
358359

359360
mockTransportReceiver.Setup(
360361
transportReceiver => transportReceiver.ReceiveMessagesAsync(
361362
maxMessages,
362363
It.IsAny<TimeSpan?>(),
363364
It.IsAny<CancellationToken>()))
364365
.Returns(
365-
Task.FromResult((IReadOnlyList<ServiceBusReceivedMessage>)
366-
new List<ServiceBusReceivedMessage> { new ServiceBusReceivedMessage(),
367-
new ServiceBusReceivedMessage()}));
366+
Task.FromResult(received));
368367
var receiver = new ServiceBusReceiver(
369368
mockConnection.Object,
370369
"queueName",
@@ -399,7 +398,7 @@ public async Task ReceiveBatchOfMessagesLogsEvents()
399398
log => log.ReceiveMessageComplete(
400399
receiver.Identifier,
401400
// the amount we actually received
402-
msgs.Count),
401+
msgs),
403402
Times.Once);
404403
}
405404

0 commit comments

Comments
 (0)