diff --git a/src/Azure/Orleans.Clustering.Cosmos/Membership/CosmosGatewayListProvider.cs b/src/Azure/Orleans.Clustering.Cosmos/Membership/CosmosGatewayListProvider.cs index cc95c5370f1..aaaa3f339a0 100644 --- a/src/Azure/Orleans.Clustering.Cosmos/Membership/CosmosGatewayListProvider.cs +++ b/src/Azure/Orleans.Clustering.Cosmos/Membership/CosmosGatewayListProvider.cs @@ -4,7 +4,7 @@ namespace Orleans.Clustering.Cosmos; -internal class CosmosGatewayListProvider : IGatewayListProvider +internal partial class CosmosGatewayListProvider : IGatewayListProvider { private readonly ILogger _logger; private readonly string _clusterId; @@ -42,7 +42,7 @@ public async Task InitializeGatewayListProvider() } catch (Exception ex) { - _logger.LogError(ex, "Error initializing Azure Cosmos DB gateway list provider"); + LogErrorInitializingGatewayListProvider(ex); throw; } } @@ -70,11 +70,23 @@ public async Task> GetGateways() } catch (Exception ex) { - _logger.LogError(ex, "Error reading gateway list from Azure Cosmos DB"); + LogErrorReadingGatewayListFromCosmosDb(ex); throw; } } private static Uri ConvertToGatewayUri(SiloEntity gateway) => SiloAddress.New(new IPEndPoint(IPAddress.Parse(gateway.Address), gateway.ProxyPort!.Value), gateway.Generation).ToGatewayUri(); -} \ No newline at end of file + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error initializing Azure Cosmos DB gateway list provider" + )] + private partial void LogErrorInitializingGatewayListProvider(Exception ex); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error reading gateway list from Azure Cosmos DB" + )] + private partial void LogErrorReadingGatewayListFromCosmosDb(Exception ex); +} diff --git a/src/Azure/Orleans.Clustering.Cosmos/Membership/CosmosMembershipTable.cs b/src/Azure/Orleans.Clustering.Cosmos/Membership/CosmosMembershipTable.cs index 40fd20a8a28..f6a20cce1c2 100644 --- a/src/Azure/Orleans.Clustering.Cosmos/Membership/CosmosMembershipTable.cs +++ b/src/Azure/Orleans.Clustering.Cosmos/Membership/CosmosMembershipTable.cs @@ -146,7 +146,7 @@ public async Task ReadRow(SiloAddress key) } else { - _logger.LogError("Initial ClusterVersionEntity entity does not exist."); + LogErrorClusterVersionEntityDoesNotExist(); } var memEntries = new List> @@ -577,4 +577,4 @@ private readonly struct MembershipEntryLogValue(MembershipEntry membershipEntry) Message = "Unable to query entry {Entry}" )] private partial void LogWarningUnableToQueryEntry(MembershipEntryLogValue entry); -} \ No newline at end of file +} diff --git a/src/Azure/Orleans.Hosting.AzureCloudServices/Hosting/ServiceRuntimeWrapper.cs b/src/Azure/Orleans.Hosting.AzureCloudServices/Hosting/ServiceRuntimeWrapper.cs index 75de191840e..7572493cee6 100644 --- a/src/Azure/Orleans.Hosting.AzureCloudServices/Hosting/ServiceRuntimeWrapper.cs +++ b/src/Azure/Orleans.Hosting.AzureCloudServices/Hosting/ServiceRuntimeWrapper.cs @@ -9,7 +9,7 @@ namespace Orleans.Runtime.Host { /// - /// Interface exposed by ServiceRuntimeWrapper for functionality provided + /// Interface exposed by ServiceRuntimeWrapper for functionality provided /// by Microsoft.WindowsAzure.ServiceRuntime. /// public interface IServiceRuntimeWrapper @@ -33,7 +33,7 @@ public interface IServiceRuntimeWrapper /// Update domain of the role instance /// int UpdateDomain { get; } - + /// /// Fault domain of the role instance /// @@ -75,16 +75,16 @@ public interface IServiceRuntimeWrapper /// - /// The purpose of this class is to wrap the functionality provided + /// The purpose of this class is to wrap the functionality provided /// by Microsoft.WindowsAzure.ServiceRuntime.dll, so that we can access it via Reflection, /// and not have a compile-time dependency on it. /// Microsoft.WindowsAzure.ServiceRuntime.dll doesn't have an official NuGet package. - /// By loading it via Reflection we solve this problem, and do not need an assembly + /// By loading it via Reflection we solve this problem, and do not need an assembly /// binding redirect for it, as we can call any compatible version. /// Microsoft.WindowsAzure.ServiceRuntime.dll hasn't changed in years, so the chance of a breaking change /// is relatively low. /// - internal class ServiceRuntimeWrapper : IServiceRuntimeWrapper, IDeploymentConfiguration + internal partial class ServiceRuntimeWrapper : IServiceRuntimeWrapper, IDeploymentConfiguration { private readonly ILogger logger; private Assembly assembly; @@ -130,7 +130,7 @@ public IList GetAllSiloNames() var list = new List(); foreach(dynamic instance in instances) list.Add(ExtractInstanceName(instance.Id,DeploymentId)); - + return list; } @@ -145,15 +145,8 @@ public IPEndPoint GetIPEndpoint(string endpointName) } catch (Exception exc) { - var endpointNames = (string)string.Join(", ", instanceEndpoints); - logger.LogError( - (int)ErrorCode.SiloEndpointConfigError, - exc, - "Unable to obtain endpoint info for role {RoleName} from role config parameter {EndpointName} -- Endpoints defined = [{EndpointNames}]", - RoleName, - endpointName, - endpointNames); - + var endpointNames = string.Join(", ", instanceEndpoints); + LogErrorUnableToObtainEndpointInfo(RoleName, endpointName, endpointNames); throw new OrleansException( $"Unable to obtain endpoint info for role {RoleName} from role config parameter {endpointName} -- Endpoints defined = [{endpointNames}]", exc); @@ -169,7 +162,7 @@ public void SubscribeForStoppingNotification(object handlerObject, EventHandler< { var handlerDelegate = handler.GetMethodInfo().CreateDelegate(stoppingEvent.EventHandlerType, handlerObject); stoppingEventAdd.Invoke(null, new object[] { handlerDelegate }); - + } public void UnsubscribeFromStoppingNotification(object handlerObject, EventHandler handler) @@ -187,8 +180,7 @@ private void Initialize() // If we are runing within a worker role Microsoft.WindowsAzure.ServiceRuntime should already be loaded if (assembly == null) { - const string msg1 = "Microsoft.WindowsAzure.ServiceRuntime is not loaded. Trying to load it with Assembly.LoadWithPartialName()."; - logger.LogWarning((int)ErrorCode.AzureServiceRuntime_NotLoaded, msg1); + LogWarningAzureServiceRuntimeNotLoaded(); // Microsoft.WindowsAzure.ServiceRuntime isn't loaded. We may be running within a web role or not in Azure. #pragma warning disable 618 @@ -196,9 +188,8 @@ private void Initialize() #pragma warning restore 618 if (assembly == null) { - const string msg2 = "Failed to find or load Microsoft.WindowsAzure.ServiceRuntime."; - logger.LogError((int)ErrorCode.AzureServiceRuntime_FailedToLoad, msg2); - throw new OrleansException(msg2); + LogErrorAzureServiceRuntimeFailedToLoad(); + throw new OrleansException("Failed to find or load Microsoft.WindowsAzure.ServiceRuntime."); } } @@ -231,5 +222,26 @@ private static string ExtractInstanceName(string instanceId, string deploymentId ? instanceId[(deploymentId.Length + 1)..] : instanceId; } + + [LoggerMessage( + Level = LogLevel.Error, + EventId = (int)ErrorCode.SiloEndpointConfigError, + Message = "Unable to obtain endpoint info for role {RoleName} from role config parameter {EndpointName} -- Endpoints defined = [{EndpointNames}]" + )] + private partial void LogErrorUnableToObtainEndpointInfo(string roleName, string endpointName, string endpointNames); + + [LoggerMessage( + Level = LogLevel.Warning, + EventId = (int)ErrorCode.AzureServiceRuntime_NotLoaded, + Message = "Microsoft.WindowsAzure.ServiceRuntime is not loaded. Trying to load it with Assembly.LoadWithPartialName()." + )] + private partial void LogWarningAzureServiceRuntimeNotLoaded(); + + [LoggerMessage( + Level = LogLevel.Error, + EventId = (int)ErrorCode.AzureServiceRuntime_FailedToLoad, + Message = "Failed to find or load Microsoft.WindowsAzure.ServiceRuntime." + )] + private partial void LogErrorAzureServiceRuntimeFailedToLoad(); } } diff --git a/src/Azure/Orleans.Reminders.AzureStorage/Storage/RemindersTableManager.cs b/src/Azure/Orleans.Reminders.AzureStorage/Storage/RemindersTableManager.cs index 9a21e879f1d..b0b35e7160e 100644 --- a/src/Azure/Orleans.Reminders.AzureStorage/Storage/RemindersTableManager.cs +++ b/src/Azure/Orleans.Reminders.AzureStorage/Storage/RemindersTableManager.cs @@ -60,7 +60,7 @@ public static (string LowerBound, string UpperBound) ConstructPartitionKeyBounds public override string ToString() => $"Reminder [PartitionKey={PartitionKey} RowKey={RowKey} GrainId={GrainReference} ReminderName={ReminderName} Deployment={DeploymentId} ServiceId={ServiceId} StartAt={StartAt} Period={Period} GrainRefConsistentHash={GrainRefConsistentHash}]"; } - internal sealed class RemindersTableManager : AzureTableDataManager + internal sealed partial class RemindersTableManager : AzureTableDataManager { private readonly string _serviceId; private readonly string _clusterId; @@ -106,8 +106,7 @@ public RemindersTableManager( } } - var queryResults = await ReadTableEntriesAndEtagsAsync(query); - return queryResults.ToList(); + return await ReadTableEntriesAndEtagsAsync(query); } internal async Task> FindReminderEntries(GrainId grainId) @@ -115,8 +114,7 @@ public RemindersTableManager( var partitionKey = ReminderTableEntry.ConstructPartitionKey(_serviceId, grainId); var (rowKeyLowerBound, rowKeyUpperBound) = ReminderTableEntry.ConstructRowKeyBounds(grainId); var query = TableClient.CreateQueryFilter($"(PartitionKey eq {partitionKey}) and ((RowKey gt {rowKeyLowerBound}) and (RowKey le {rowKeyUpperBound}))"); - var queryResults = await ReadTableEntriesAndEtagsAsync(query); - return queryResults.ToList(); + return await ReadTableEntriesAndEtagsAsync(query); } internal async Task<(ReminderTableEntry Entity, string ETag)> FindReminderEntry(GrainId grainId, string reminderName) @@ -140,11 +138,9 @@ internal async Task UpsertRow(ReminderTableEntry reminderEntry) } catch(Exception exc) { - HttpStatusCode httpStatusCode; - string restStatus; - if (AzureTableUtils.EvaluateException(exc, out httpStatusCode, out restStatus)) + if (AzureTableUtils.EvaluateException(exc, out var httpStatusCode, out var restStatus)) { - if (Logger.IsEnabled(LogLevel.Trace)) Logger.LogTrace("UpsertRow failed with HTTP status code: {HttpStatusCode}, REST status: {RestStatus}", httpStatusCode, restStatus); + LogTraceUpsertRowFailed(Logger, httpStatusCode, restStatus); if (AzureTableUtils.IsContentionError(httpStatusCode)) return null; // false; } throw; @@ -161,15 +157,9 @@ internal async Task DeleteReminderEntryConditionally(ReminderTableEntry re } catch(Exception exc) { - HttpStatusCode httpStatusCode; - string restStatus; - if (AzureTableUtils.EvaluateException(exc, out httpStatusCode, out restStatus)) + if (AzureTableUtils.EvaluateException(exc, out var httpStatusCode, out var restStatus)) { - if (Logger.IsEnabled(LogLevel.Trace)) - Logger.LogTrace( - "DeleteReminderEntryConditionally failed with HTTP status code: {HttpStatusCode}, REST status: {RestStatus}", - httpStatusCode, - restStatus); + LogTraceDeleteReminderEntryConditionallyFailed(Logger, httpStatusCode, restStatus); if (AzureTableUtils.IsContentionError(httpStatusCode)) return false; } throw; @@ -189,7 +179,7 @@ internal async Task DeleteTableEntries() foreach (var entriesPerPartition in groupedByHash.Values) { - foreach (var batch in entriesPerPartition.BatchIEnumerable(this.StoragePolicyOptions.MaxBulkUpdateRows)) + foreach (var batch in entriesPerPartition.BatchIEnumerable(this.StoragePolicyOptions.MaxBulkUpdateRows)) { tasks.Add(DeleteTableEntriesAsync(batch)); } @@ -197,5 +187,17 @@ internal async Task DeleteTableEntries() await Task.WhenAll(tasks); } + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "UpsertRow failed with HTTP status code: {HttpStatusCode}, REST status: {RestStatus}" + )] + private static partial void LogTraceUpsertRowFailed(ILogger logger, HttpStatusCode httpStatusCode, string restStatus); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "DeleteReminderEntryConditionally failed with HTTP status code: {HttpStatusCode}, REST status: {RestStatus}" + )] + private static partial void LogTraceDeleteReminderEntryConditionallyFailed(ILogger logger, HttpStatusCode httpStatusCode, string restStatus); } } diff --git a/src/Azure/Orleans.Streaming.AzureStorage/Providers/Streams/AzureQueue/AzureQueueAdapterReceiver.cs b/src/Azure/Orleans.Streaming.AzureStorage/Providers/Streams/AzureQueue/AzureQueueAdapterReceiver.cs index 935b786e1fb..725cb25f115 100644 --- a/src/Azure/Orleans.Streaming.AzureStorage/Providers/Streams/AzureQueue/AzureQueueAdapterReceiver.cs +++ b/src/Azure/Orleans.Streaming.AzureStorage/Providers/Streams/AzureQueue/AzureQueueAdapterReceiver.cs @@ -14,7 +14,7 @@ namespace Orleans.Providers.Streams.AzureQueue /// /// Receives batches of messages from a single partition of a message queue. /// - internal class AzureQueueAdapterReceiver : IQueueAdapterReceiver + internal partial class AzureQueueAdapterReceiver : IQueueAdapterReceiver { private AzureQueueDataManager queue; private long lastReadMessage; @@ -131,9 +131,7 @@ public async Task MessagesDeliveredAsync(IList messages) } catch (Exception exc) { - logger.LogWarning((int)AzureQueueErrorCode.AzureQueue_15, - exc, - "Exception upon DeleteQueueMessage on queue {QueueName}. Ignoring.", this.azureQueueName); + LogWarningOnDeleteQueueMessage(exc, this.azureQueueName); } } finally @@ -142,6 +140,13 @@ public async Task MessagesDeliveredAsync(IList messages) } } + [LoggerMessage( + Level = LogLevel.Warning, + EventId = (int)AzureQueueErrorCode.AzureQueue_15, + Message = "Exception upon DeleteQueueMessage on queue {QueueName}. Ignoring." + )] + private partial void LogWarningOnDeleteQueueMessage(Exception exception, string queueName); + private class PendingDelivery { public PendingDelivery(StreamSequenceToken token, QueueMessage message) diff --git a/src/Azure/Orleans.Streaming.AzureStorage/Storage/AzureQueueDataManager.cs b/src/Azure/Orleans.Streaming.AzureStorage/Storage/AzureQueueDataManager.cs index b0ba451d03e..116d254e973 100644 --- a/src/Azure/Orleans.Streaming.AzureStorage/Storage/AzureQueueDataManager.cs +++ b/src/Azure/Orleans.Streaming.AzureStorage/Storage/AzureQueueDataManager.cs @@ -102,7 +102,7 @@ private ValueTask GetQueueClient() } return GetQueueClientAsync(); - async ValueTask GetQueueClientAsync() => _queueClient ??= await GetCloudQueueClient(options, logger); + async ValueTask GetQueueClientAsync() => _queueClient ??= await GetCloudQueueClient(options); } /// @@ -368,11 +368,11 @@ private void ReportErrorAndRethrow(Exception exc, string operation, AzureQueueEr var errMsg = string.Format( "Error doing {0} for Azure storage queue {1} " + Environment.NewLine + "Exception = {2}", operation, QueueName, exc); - logger.LogError((int)errorCode, exc, "{Message}", errMsg); + logger.LogError((int)errorCode, exc, "{Message}", errMsg); // TODO: pending on https://github.com/dotnet/runtime/issues/110570 throw new AggregateException(errMsg, exc); } - private async Task GetCloudQueueClient(AzureQueueOptions options, ILogger logger) + private async Task GetCloudQueueClient(AzureQueueOptions options) { try { diff --git a/src/Azure/Orleans.Streaming.EventHubs/OrleansServiceBusErrorCode.cs b/src/Azure/Orleans.Streaming.EventHubs/OrleansServiceBusErrorCode.cs index 459eb47b004..96b61649b6e 100644 --- a/src/Azure/Orleans.Streaming.EventHubs/OrleansServiceBusErrorCode.cs +++ b/src/Azure/Orleans.Streaming.EventHubs/OrleansServiceBusErrorCode.cs @@ -1,6 +1,3 @@ -using System; -using Microsoft.Extensions.Logging; - namespace Orleans.Streaming.EventHubs { /// @@ -16,37 +13,4 @@ internal enum OrleansEventHubErrorCode FailedPartitionRead = ServiceBus + 1, RetryReceiverInit = ServiceBus + 2, } - - internal static class LoggerExtensions - { - internal static void Debug(this ILogger logger, OrleansEventHubErrorCode errorCode, string format, params object[] args) - { - logger.LogDebug((int)errorCode, format, args); - } - - internal static void Trace(this ILogger logger, OrleansEventHubErrorCode errorCode, string format, params object[] args) - { - logger.LogTrace((int)errorCode, format, args); - } - - internal static void Info(this ILogger logger, OrleansEventHubErrorCode errorCode, string format, params object[] args) - { - logger.LogInformation((int)errorCode, format, args); - } - - internal static void Warn(this ILogger logger, OrleansEventHubErrorCode errorCode, string format, params object[] args) - { - logger.LogWarning((int)errorCode, format, args); - } - - internal static void Warn(this ILogger logger, OrleansEventHubErrorCode errorCode, string message, Exception exception) - { - logger.LogWarning((int)errorCode, exception, message); - } - - internal static void Error(this ILogger logger, OrleansEventHubErrorCode errorCode, string message, Exception exception = null) - { - logger.LogError((int)errorCode, exception, message); - } - } } diff --git a/src/Azure/Orleans.Streaming.EventHubs/Providers/EventDataGeneratorStreamProvider/EventDataGeneratorAdapterFactory.cs b/src/Azure/Orleans.Streaming.EventHubs/Providers/EventDataGeneratorStreamProvider/EventDataGeneratorAdapterFactory.cs index f483ae66358..f0524d8b535 100644 --- a/src/Azure/Orleans.Streaming.EventHubs/Providers/EventDataGeneratorStreamProvider/EventDataGeneratorAdapterFactory.cs +++ b/src/Azure/Orleans.Streaming.EventHubs/Providers/EventDataGeneratorStreamProvider/EventDataGeneratorAdapterFactory.cs @@ -17,7 +17,7 @@ namespace Orleans.Streaming.EventHubs.Testing /// This is a persistent stream provider adapter that generates it's own events rather than reading them from Eventhub. /// This is primarily for test purposes. /// - public class EventDataGeneratorAdapterFactory : EventHubAdapterFactory, IControllable + public partial class EventDataGeneratorAdapterFactory : EventHubAdapterFactory, IControllable { private readonly EventDataGeneratorStreamOptions ehGeneratorOptions; @@ -81,12 +81,12 @@ private void RandomlyPlaceStreamToQueue(StreamRandomPlacementArg args) if (EventHubReceivers.TryGetValue(queueToAssign, out var receiverToAssign)) { receiverToAssign.ConfigureDataGeneratorForStream(args.StreamId); - logger.LogInformation("Stream {StreamId} is assigned to queue {QueueId}", args.StreamId, queueToAssign); + LogInfoStreamAssignedToQueue(logger, args.StreamId, queueToAssign); } } else { - logger.LogInformation("Cannot get queues in the cluster, current streamQueueMapper is not EventHubQueueMapper"); + LogInfoCannotGetQueues(logger); } } @@ -186,10 +186,22 @@ public virtual Task ExecuteCommand(int command, object arg) IEventHubDataAdapter dataAdapter = services.GetKeyedService(name) ?? services.GetService() ?? ActivatorUtilities.CreateInstance(services); - var factory = ActivatorUtilities.CreateInstance(services, name, generatorOptions, ehOptions, receiverOptions, cacheOptions, + var factory = ActivatorUtilities.CreateInstance(services, name, generatorOptions, ehOptions, receiverOptions, cacheOptions, evictionOptions, statisticOptions, dataAdapter); factory.Init(); return factory; } + + [LoggerMessage( + Level = LogLevel.Information, + Message = "Stream {StreamId} is assigned to queue {QueueId}" + )] + private static partial void LogInfoStreamAssignedToQueue(ILogger logger, StreamId streamId, QueueId queueId); + + [LoggerMessage( + Level = LogLevel.Information, + Message = "Cannot get queues in the cluster, current streamQueueMapper is not EventHubQueueMapper" + )] + private static partial void LogInfoCannotGetQueues(ILogger logger); } } diff --git a/src/Azure/Orleans.Streaming.EventHubs/Providers/EventDataGeneratorStreamProvider/EventHubPartitionDataGenerator.cs b/src/Azure/Orleans.Streaming.EventHubs/Providers/EventDataGeneratorStreamProvider/EventHubPartitionDataGenerator.cs index 1f94b7d95a5..ff56115439d 100644 --- a/src/Azure/Orleans.Streaming.EventHubs/Providers/EventDataGeneratorStreamProvider/EventHubPartitionDataGenerator.cs +++ b/src/Azure/Orleans.Streaming.EventHubs/Providers/EventDataGeneratorStreamProvider/EventHubPartitionDataGenerator.cs @@ -13,7 +13,7 @@ namespace Orleans.Streaming.EventHubs.Testing /// /// Generate data for one stream /// - public class SimpleStreamEventDataGenerator : IStreamDataGenerator + public partial class SimpleStreamEventDataGenerator : IStreamDataGenerator { /// public StreamId StreamId { get; set; } @@ -65,8 +65,7 @@ public bool TryReadEvents(int maxCount, out IEnumerable events) sequenceNumber: this.SequenceNumberCounter.Value); eventDataList.Add(wrapper); - - this.logger.LogInformation("Generate data of SequenceNumber {SequenceNumber} for stream {StreamId}", SequenceNumberCounter.Value, this.StreamId); + LogInfoGenerateData(this.SequenceNumberCounter.Value, this.StreamId); } events = eventDataList; @@ -92,12 +91,18 @@ public WrappedEventData(ReadOnlyMemory eventBody, IDictionary /// EHPartitionDataGenerator generate data for a EH partition, which can include data from different streams /// - public class EventHubPartitionDataGenerator : IDataGenerator, IStreamDataGeneratingController + public partial class EventHubPartitionDataGenerator : IDataGenerator, IStreamDataGeneratingController { //differnt stream in the same partition should use the same sequenceNumberCounter private readonly EventDataGeneratorStreamOptions options; @@ -124,7 +129,7 @@ public void AddDataGeneratorForStream(StreamId streamId) { var generator = this.generatorFactory(streamId); generator.SequenceNumberCounter = sequenceNumberCounter; - this.logger.LogInformation("Data generator set up on stream {StreamId}.", streamId); + LogInfoOnStreamSetup(streamId); this.generators.Add(generator); } /// @@ -134,7 +139,7 @@ public void StopProducingOnStream(StreamId streamId) if (generator.StreamId.Equals(streamId)) { generator.ShouldProduce = false; - this.logger.LogInformation("Stop producing data on stream {StreamId}.", streamId); + LogInfoOnStreamStop(streamId); } }); } @@ -173,5 +178,17 @@ public bool TryReadEvents(int maxCount, out IEnumerable events) events = eventDataList.AsEnumerable(); return eventDataList.Count > 0; } + + [LoggerMessage( + Level = LogLevel.Information, + Message = "Data generator set up on stream {StreamId}." + )] + private partial void LogInfoOnStreamSetup(StreamId streamId); + + [LoggerMessage( + Level = LogLevel.Information, + Message = "Stop producing data on stream {StreamId}." + )] + private partial void LogInfoOnStreamStop(StreamId streamId); } } diff --git a/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/CachePressureMonitors/AggregatedCachePressureMonitor.cs b/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/CachePressureMonitors/AggregatedCachePressureMonitor.cs index a110ee955a0..8ea38be62a1 100644 --- a/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/CachePressureMonitors/AggregatedCachePressureMonitor.cs +++ b/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/CachePressureMonitors/AggregatedCachePressureMonitor.cs @@ -9,7 +9,7 @@ namespace Orleans.Streaming.EventHubs /// /// Aggregated cache pressure monitor /// - public class AggregatedCachePressureMonitor : List, ICachePressureMonitor + public partial class AggregatedCachePressureMonitor : List, ICachePressureMonitor { private bool isUnderPressure; private readonly ILogger logger; @@ -63,12 +63,28 @@ public bool IsUnderPressure(DateTime utcNow) { this.isUnderPressure = underPressure; this.CacheMonitor?.TrackCachePressureMonitorStatusChange(this.GetType().Name, this.isUnderPressure, null, null, null); - logger.LogInformation( - this.isUnderPressure - ? "Ingesting messages too fast. Throttling message reading." - : "Message ingestion is healthy."); + if (this.isUnderPressure) + { + LogInfoIngestingMessagesTooFast(); + } + else + { + LogInfoMessageIngestionIsHealthy(); + } } return underPressure; } + + [LoggerMessage( + Level = LogLevel.Information, + Message = "Ingesting messages too fast. Throttling message reading." + )] + private partial void LogInfoIngestingMessagesTooFast(); + + [LoggerMessage( + Level = LogLevel.Information, + Message = "Message ingestion is healthy." + )] + private partial void LogInfoMessageIngestionIsHealthy(); } } diff --git a/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/CachePressureMonitors/AveragingCachePressureMonitor.cs b/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/CachePressureMonitors/AveragingCachePressureMonitor.cs index c332070290d..ff54162d241 100644 --- a/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/CachePressureMonitors/AveragingCachePressureMonitor.cs +++ b/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/CachePressureMonitors/AveragingCachePressureMonitor.cs @@ -9,7 +9,7 @@ namespace Orleans.Streaming.EventHubs /// Cache pressure monitor whose back pressure algorithm is based on averaging pressure value /// over all pressure contribution /// - public class AveragingCachePressureMonitor : ICachePressureMonitor + public partial class AveragingCachePressureMonitor : ICachePressureMonitor { /// /// Cache monitor which is used to report cache related metrics @@ -86,13 +86,29 @@ private void CalculatePressure() if (isUnderPressure != wasUnderPressure) { this.CacheMonitor?.TrackCachePressureMonitorStatusChange(this.GetType().Name, isUnderPressure, cachePressureContributionCount, pressure, this.flowControlThreshold); - if(this.logger.IsEnabled(LogLevel.Debug)) - logger.LogDebug(isUnderPressure - ? $"Ingesting messages too fast. Throttling message reading. AccumulatedCachePressure: {accumulatedCachePressure}, Contributions: {cachePressureContributionCount}, AverageCachePressure: {pressure}, Threshold: {flowControlThreshold}" - : $"Message ingestion is healthy. AccumulatedCachePressure: {accumulatedCachePressure}, Contributions: {cachePressureContributionCount}, AverageCachePressure: {pressure}, Threshold: {flowControlThreshold}"); + if (isUnderPressure) + { + LogDebugIngestingMessagesTooFast(accumulatedCachePressure, cachePressureContributionCount, pressure, flowControlThreshold); + } + else + { + LogDebugMessageIngestionIsHealthy(accumulatedCachePressure, cachePressureContributionCount, pressure, flowControlThreshold); + } } cachePressureContributionCount = 0.0; accumulatedCachePressure = 0.0; } + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Ingesting messages too fast. Throttling message reading. AccumulatedCachePressure: {AccumulatedCachePressure}, Contributions: {Contributions}, AverageCachePressure: {AverageCachePressure}, Threshold: {FlowControlThreshold}" + )] + private partial void LogDebugIngestingMessagesTooFast(double accumulatedCachePressure, double contributions, double averageCachePressure, double flowControlThreshold); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Message ingestion is healthy. AccumulatedCachePressure: {AccumulatedCachePressure}, Contributions: {Contributions}, AverageCachePressure: {AverageCachePressure}, Threshold: {FlowControlThreshold}" + )] + private partial void LogDebugMessageIngestionIsHealthy(double accumulatedCachePressure, double contributions, double averageCachePressure, double flowControlThreshold); } } diff --git a/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/CachePressureMonitors/SlowConsumingPressureMonitor.cs b/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/CachePressureMonitors/SlowConsumingPressureMonitor.cs index 372ef4378bf..6f5d8e45762 100644 --- a/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/CachePressureMonitors/SlowConsumingPressureMonitor.cs +++ b/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/CachePressureMonitors/SlowConsumingPressureMonitor.cs @@ -7,7 +7,7 @@ namespace Orleans.Streaming.EventHubs /// /// Pressure monitor which is in favor of the slow consumer in the cache /// - public class SlowConsumingPressureMonitor : ICachePressureMonitor + public partial class SlowConsumingPressureMonitor : ICachePressureMonitor { /// /// DefaultPressureWindowSize @@ -101,15 +101,11 @@ public bool IsUnderPressure(DateTime utcNow) if (underPressure && !this.wasUnderPressure) { - //if under pressure, extend the nextCheckedTime, make sure wasUnderPressure is true for a whole window + //if under pressure, extend the nextCheckedTime, make sure wasUnderPressure is true for a whole window this.wasUnderPressure = underPressure; this.nextCheckedTime = utcNow + this.PressureWindowSize; this.CacheMonitor?.TrackCachePressureMonitorStatusChange(this.GetType().Name, underPressure, null, biggestPressureInCurrentWindow, this.FlowControlThreshold); - if(logger.IsEnabled(LogLevel.Debug)) - logger.LogDebug( - "Ingesting messages too fast. Throttling message reading. BiggestPressureInCurrentPeriod: {BiggestPressureInCurrentWindow}, Threshold: {FlowControlThreshold}", - biggestPressureInCurrentWindow, - FlowControlThreshold); + LogDebugIngestingMessagesTooFast(biggestPressureInCurrentWindow, FlowControlThreshold); this.biggestPressureInCurrentWindow = 0; } @@ -122,16 +118,24 @@ public bool IsUnderPressure(DateTime utcNow) if (this.wasUnderPressure && !underPressure) { this.CacheMonitor?.TrackCachePressureMonitorStatusChange(this.GetType().Name, underPressure, null, biggestPressureInCurrentWindow, this.FlowControlThreshold); - if (logger.IsEnabled(LogLevel.Debug)) - logger.LogDebug( - "Message ingestion is healthy. BiggestPressureInCurrentPeriod: {BiggestPressureInCurrentWindow}, Threshold: {FlowControlThreshold}", - biggestPressureInCurrentWindow, - FlowControlThreshold); + LogDebugMessageIngestionIsHealthy(biggestPressureInCurrentWindow, FlowControlThreshold); } this.wasUnderPressure = underPressure; } return this.wasUnderPressure; } + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Ingesting messages too fast. Throttling message reading. BiggestPressureInCurrentPeriod: {BiggestPressureInCurrentWindow}, Threshold: {FlowControlThreshold}" + )] + private partial void LogDebugIngestingMessagesTooFast(double biggestPressureInCurrentWindow, double flowControlThreshold); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Message ingestion is healthy. BiggestPressureInCurrentPeriod: {BiggestPressureInCurrentWindow}, Threshold: {FlowControlThreshold}" + )] + private partial void LogDebugMessageIngestionIsHealthy(double biggestPressureInCurrentWindow, double flowControlThreshold); } } diff --git a/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/EventHubAdapterReceiver.cs b/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/EventHubAdapterReceiver.cs index f5fafb3e4df..23d59d113eb 100644 --- a/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/EventHubAdapterReceiver.cs +++ b/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/EventHubAdapterReceiver.cs @@ -33,7 +33,7 @@ public class EventHubPartitionSettings public string Partition { get; set; } } - internal class EventHubAdapterReceiver : IQueueAdapterReceiver, IQueueCache + internal partial class EventHubAdapterReceiver : IQueueAdapterReceiver, IQueueCache { public const int MaxMessagesPerRead = 1000; private static readonly TimeSpan ReceiveTimeout = TimeSpan.FromSeconds(5); @@ -88,7 +88,7 @@ public EventHubAdapterReceiver(EventHubPartitionSettings settings, public Task Initialize(TimeSpan timeout) { - this.logger.LogInformation("Initializing EventHub partition {EventHubName}-{Partition}.", this.settings.Hub.EventHubName, this.settings.Partition); + LogInfoInitializingEventHubPartition(this.settings.Hub.EventHubName, this.settings.Partition); // if receiver was already running, do nothing return ReceiverRunning == Interlocked.Exchange(ref this.receiverState, ReceiverRunning) @@ -137,8 +137,7 @@ public async Task> GetQueueMessagesAsync(int maxCount) // if receiver initialization failed, retry if (this.receiver == null) { - this.logger.Warn(OrleansEventHubErrorCode.FailedPartitionRead, - "Retrying initialization of EventHub partition {0}-{1}.", this.settings.Hub.EventHubName, this.settings.Partition); + LogWarningRetryingInitializationOfEventHubPartition(this.settings.Hub.EventHubName, this.settings.Partition); await Initialize(); if (this.receiver == null) { @@ -160,9 +159,7 @@ public async Task> GetQueueMessagesAsync(int maxCount) { watch.Stop(); this.monitor?.TrackRead(false, watch.Elapsed, ex); - this.logger.Warn(OrleansEventHubErrorCode.FailedPartitionRead, - "Failed to read from EventHub partition {0}-{1}. : Exception: {2}.", this.settings.Hub.EventHubName, - this.settings.Partition, ex); + LogWarningFailedToReadFromEventHubPartition(this.settings.Hub.EventHubName, this.settings.Partition, ex); throw; } @@ -237,7 +234,7 @@ public async Task Shutdown(TimeSpan timeout) return; } - this.logger.LogInformation("Stopping reading from EventHub partition {EventHubName}-{Partition}", this.settings.Hub.EventHubName, this.settings.Partition); + LogInfoStoppingReadingFromEventHubPartition(this.settings.Hub.EventHubName, this.settings.Partition); // clear cache and receiver IEventHubQueueCache localCache = Interlocked.Exchange(ref this.cache, null); @@ -345,5 +342,31 @@ public void RecordDeliveryFailure() { } } + + [LoggerMessage( + Level = LogLevel.Information, + Message = "Initializing EventHub partition {EventHubName}-{Partition}." + )] + private partial void LogInfoInitializingEventHubPartition(string eventHubName, string partition); + + [LoggerMessage( + Level = LogLevel.Information, + Message = "Stopping reading from EventHub partition {EventHubName}-{Partition}" + )] + private partial void LogInfoStoppingReadingFromEventHubPartition(string eventHubName, string partition); + + [LoggerMessage( + Level = LogLevel.Warning, + EventId = (int)OrleansEventHubErrorCode.FailedPartitionRead, + Message = "Retrying initialization of EventHub partition {EventHubName}-{Partition}." + )] + private partial void LogWarningRetryingInitializationOfEventHubPartition(string eventHubName, string partition); + + [LoggerMessage( + Level = LogLevel.Warning, + EventId = (int)OrleansEventHubErrorCode.FailedPartitionRead, + Message = "Failed to read from EventHub partition {EventHubName}-{Partition}" + )] + private partial void LogWarningFailedToReadFromEventHubPartition(string eventHubName, string partition, Exception exception); } -} \ No newline at end of file +} diff --git a/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/EventHubCheckpointer.cs b/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/EventHubCheckpointer.cs index 819e2e513c2..76d988e10b3 100644 --- a/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/EventHubCheckpointer.cs +++ b/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/EventHubCheckpointer.cs @@ -40,7 +40,7 @@ public static IStreamQueueCheckpointerFactory CreateFactory(IServiceProvider ser /// /// This class stores EventHub partition checkpointer information (a partition offset) in azure table storage. /// - public class EventHubCheckpointer : IStreamQueueCheckpointer + public partial class EventHubCheckpointer : IStreamQueueCheckpointer { private readonly AzureTableDataManager dataManager; private readonly TimeSpan persistInterval; @@ -86,11 +86,7 @@ private EventHubCheckpointer(AzureTableStreamCheckpointerOptions options, string throw new ArgumentNullException(nameof(partition)); } this.logger = loggerFactory.CreateLogger(); - this.logger.LogInformation( - "Creating EventHub checkpointer for partition {Partition} of stream provider {StreamProviderName} with serviceId {ServiceId}.", - partition, - streamProviderName, - serviceId); + LogCreatingEventHubCheckpointer(partition, streamProviderName, serviceId); persistInterval = options.PersistInterval; dataManager = new AzureTableDataManager( options, @@ -142,5 +138,11 @@ public void Update(string offset, DateTime utcNow) inProgressSave = dataManager.UpsertTableEntryAsync(entity); inProgressSave.Ignore(); } + + [LoggerMessage( + Level = LogLevel.Information, + Message = "Creating EventHub checkpointer for partition {Partition} of stream provider {StreamProviderName} with serviceId {ServiceId}." + )] + private partial void LogCreatingEventHubCheckpointer(string partition, string streamProviderName, string serviceId); } } diff --git a/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/EventHubQueueCache.cs b/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/EventHubQueueCache.cs index 2b3897a4e9e..c46a580a275 100644 --- a/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/EventHubQueueCache.cs +++ b/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/EventHubQueueCache.cs @@ -11,7 +11,7 @@ namespace Orleans.Streaming.EventHubs /// /// EventHub queue cache /// - public class EventHubQueueCache : IEventHubQueueCache + public partial class EventHubQueueCache : IEventHubQueueCache { public string Partition { get; private set; } @@ -161,14 +161,13 @@ public bool TryGetNextMessage(object cursorObj, out IBatchContainer message) /// private void OnPurge(CachedMessage? lastItemPurged, CachedMessage? newestItem) { - if (logger.IsEnabled(LogLevel.Debug) && lastItemPurged.HasValue && newestItem.HasValue) + if (lastItemPurged.HasValue && newestItem.HasValue) { - logger.LogDebug( - "CachePeriod: EnqueueTimeUtc: {OldestEnqueueTimeUtc} to {NewestEnqueueTimeUtc}, DequeueTimeUtc: {OldestDequeueTimeUtc} to {NewestDequeueTimeUtc}", - LogFormatter.PrintDate(lastItemPurged.Value.EnqueueTimeUtc), - LogFormatter.PrintDate(newestItem.Value.EnqueueTimeUtc), - LogFormatter.PrintDate(lastItemPurged.Value.DequeueTimeUtc), - LogFormatter.PrintDate(newestItem.Value.DequeueTimeUtc)); + LogDebugCachePeriod( + new(lastItemPurged.Value.EnqueueTimeUtc), + new(newestItem.Value.EnqueueTimeUtc), + new(lastItemPurged.Value.DequeueTimeUtc), + new(newestItem.Value.DequeueTimeUtc)); } if (lastItemPurged.HasValue) { @@ -220,5 +219,20 @@ private ArraySegment GetSegment(int size) } return segment; } + + private readonly struct DateTimeLogRecord(DateTime ts) + { + public override string ToString() => LogFormatter.PrintDate(ts); + } + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "CachePeriod: EnqueueTimeUtc: {OldestEnqueueTimeUtc} to {NewestEnqueueTimeUtc}, DequeueTimeUtc: {OldestDequeueTimeUtc} to {NewestDequeueTimeUtc}" + )] + private partial void LogDebugCachePeriod( + DateTimeLogRecord oldestEnqueueTimeUtc, + DateTimeLogRecord newestEnqueueTimeUtc, + DateTimeLogRecord oldestDequeueTimeUtc, + DateTimeLogRecord newestDequeueTimeUtc); } } diff --git a/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/IEventHubReceiver.cs b/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/IEventHubReceiver.cs index 8da0e433f6a..1180963ebfb 100644 --- a/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/IEventHubReceiver.cs +++ b/src/Azure/Orleans.Streaming.EventHubs/Providers/Streams/EventHub/IEventHubReceiver.cs @@ -32,7 +32,7 @@ public interface IEventHubReceiver /// /// pass through decorator class for EventHubReceiver /// - internal class EventHubReceiverProxy : IEventHubReceiver + internal partial class EventHubReceiverProxy : IEventHubReceiver { private readonly PartitionReceiver client; @@ -61,20 +61,20 @@ EventPosition GetEventPosition() throw new InvalidOperationException("Offset must be a number."); } - logger.LogInformation("Starting to read from EventHub partition {0}-{1} at offset {2}", options.EventHubName, partitionSettings.Partition, offset); + LogInfoStartingRead(logger, options.EventHubName, partitionSettings.Partition, offset); eventPosition = EventPosition.FromOffset(longOffset, true); } // else, if configured to start from now, start reading from most recent data else if (partitionSettings.ReceiverOptions.StartFromNow) { eventPosition = EventPosition.Latest; - logger.LogInformation("Starting to read latest messages from EventHub partition {0}-{1}.", options.EventHubName, partitionSettings.Partition); + LogInfoStartingReadLatest(logger, options.EventHubName, partitionSettings.Partition); } else // else, start reading from begining of the partition { eventPosition = EventPosition.Earliest; - logger.LogInformation("Starting to read messages from begining of EventHub partition {0}-{1}.", options.EventHubName, partitionSettings.Partition); + LogInfoStartingReadBegin(logger, options.EventHubName, partitionSettings.Partition); } return eventPosition; @@ -90,5 +90,23 @@ public async Task CloseAsync() { await client.CloseAsync(); } + + [LoggerMessage( + Level = LogLevel.Information, + Message = "Starting to read from EventHub partition {EventHubName}-{Partition} at offset {Offset}" + )] + private static partial void LogInfoStartingRead(ILogger logger, string eventHubName, string partition, string offset); + + [LoggerMessage( + Level = LogLevel.Information, + Message = "Starting to read latest messages from EventHub partition {EventHubName}-{Partition}." + )] + private static partial void LogInfoStartingReadLatest(ILogger logger, string eventHubName, string partition); + + [LoggerMessage( + Level = LogLevel.Information, + Message = "Starting to read messages from begining of EventHub partition {EventHubName}-{Partition}." + )] + private static partial void LogInfoStartingReadBegin(ILogger logger, string eventHubName, string partition); } } diff --git a/src/Azure/Orleans.Transactions.AzureStorage/TransactionalState/AzureTableTransactionalStateStorage.cs b/src/Azure/Orleans.Transactions.AzureStorage/TransactionalState/AzureTableTransactionalStateStorage.cs index 633cef38f1f..f4b1ee94582 100644 --- a/src/Azure/Orleans.Transactions.AzureStorage/TransactionalState/AzureTableTransactionalStateStorage.cs +++ b/src/Azure/Orleans.Transactions.AzureStorage/TransactionalState/AzureTableTransactionalStateStorage.cs @@ -10,7 +10,7 @@ namespace Orleans.Transactions.AzureStorage { - public class AzureTableTransactionalStateStorage : ITransactionalStateStorage + public partial class AzureTableTransactionalStateStorage : ITransactionalStateStorage where TState : class, new() { private readonly TableClient table; @@ -45,8 +45,7 @@ public async Task> Load() if (string.IsNullOrEmpty(key.ETag.ToString())) { - if (logger.IsEnabled(LogLevel.Debug)) - logger.LogDebug("{Partition} Loaded v0, fresh", partition); + LogDebugLoadedV0Fresh(partition); // first time load return new TransactionalStorageLoadResponse(); @@ -63,7 +62,7 @@ public async Task> Load() if (!FindState(this.key.CommittedSequenceId, out var pos)) { var error = $"Storage state corrupted: no record for committed state v{this.key.CommittedSequenceId}"; - logger.LogCritical($"{partition} {error}"); + LogCriticalPartitionError(partition, error); throw new InvalidOperationException(error); } committedState = states[pos].Value.GetState(this.jsonSettings); @@ -101,8 +100,7 @@ public async Task> Load() entity.StateJson = null; } - if (logger.IsEnabled(LogLevel.Debug)) - logger.LogDebug("{PartitionKey} Loaded v{CommittedSequenceId} rows={Data}", partition, this.key.CommittedSequenceId, string.Join(",", states.Select(s => s.Key.ToString("x16")))); + LogDebugLoadedPartitionKeyRows(partition, this.key.CommittedSequenceId, new(states)); TransactionalStateMetaData metadata = JsonConvert.DeserializeObject(this.key.Metadata, this.jsonSettings); return new TransactionalStorageLoadResponse(this.key.ETag.ToString(), committedState, this.key.CommittedSequenceId, metadata, PrepareRecordsToRecover); @@ -110,12 +108,11 @@ public async Task> Load() } catch (Exception ex) { - this.logger.LogError(ex, "Transactional state load failed"); + LogErrorTransactionalStateLoadFailed(ex); throw; } } - public async Task Store(string expectedETag, TransactionalStateMetaData metadata, List> statesToPrepare, long? commitUpTo, long? abortAfter) { var keyETag = key.ETag.ToString(); @@ -139,8 +136,7 @@ public async Task Store(string expectedETag, TransactionalStateMetaData key.ETag = batchOperation.KeyETag; states.RemoveAt(states.Count - 1); - if (logger.IsEnabled(LogLevel.Trace)) - logger.LogTrace("{PartitionKey}.{RowKey} Delete {TransactionId}", partition, entity.RowKey, entity.TransactionId); + LogTraceDeleteTransaction(partition, entity.RowKey, entity.TransactionId); } } @@ -161,8 +157,7 @@ public async Task Store(string expectedETag, TransactionalStateMetaData await batchOperation.Add(new TableTransactionAction(TableTransactionActionType.UpdateReplace, existing.Entity, existing.ETag)).ConfigureAwait(false); key.ETag = batchOperation.KeyETag; - if (logger.IsEnabled(LogLevel.Trace)) - logger.LogTrace("{PartitionKey}.{RowKey} Update {TransactionId}", partition, existing.RowKey, existing.TransactionId); + LogTraceUpdateTransaction(partition, existing.RowKey, existing.TransactionId); } else { @@ -171,8 +166,7 @@ public async Task Store(string expectedETag, TransactionalStateMetaData key.ETag = batchOperation.KeyETag; states.Insert(pos, new KeyValuePair(s.SequenceId, entity)); - if (logger.IsEnabled(LogLevel.Trace)) - logger.LogTrace("{PartitionKey}.{RowKey} Insert {TransactionId}", partition, entity.RowKey, entity.TransactionId); + LogTraceInsertTransaction(partition, entity.RowKey, entity.TransactionId); } } @@ -187,16 +181,14 @@ public async Task Store(string expectedETag, TransactionalStateMetaData await batchOperation.Add(new TableTransactionAction(TableTransactionActionType.Add, key)).ConfigureAwait(false); key.ETag = batchOperation.KeyETag; - if (logger.IsEnabled(LogLevel.Trace)) - logger.LogTrace("{PartitionKey}.{RowKey} Insert. v{CommittedSequenceId}, {CommitRecordsCount}c", partition, KeyEntity.RK, this.key.CommittedSequenceId, metadata.CommitRecords.Count); + LogTraceInsertWithCount(partition, KeyEntity.RK, this.key.CommittedSequenceId, metadata.CommitRecords.Count); } else { await batchOperation.Add(new TableTransactionAction(TableTransactionActionType.UpdateReplace, key, key.ETag)).ConfigureAwait(false); key.ETag = batchOperation.KeyETag; - if (logger.IsEnabled(LogLevel.Trace)) - logger.LogTrace("{PartitionKey}.{RowKey} Update. v{CommittedSequenceId}, {CommitRecordsCount}c", partition, KeyEntity.RK, this.key.CommittedSequenceId, metadata.CommitRecords.Count); + LogTraceUpdateWithCount(partition, KeyEntity.RK, this.key.CommittedSequenceId, metadata.CommitRecords.Count); } // fourth, remove obsolete records @@ -208,16 +200,14 @@ public async Task Store(string expectedETag, TransactionalStateMetaData await batchOperation.Add(new TableTransactionAction(TableTransactionActionType.Delete, states[i].Value.Entity, states[i].Value.ETag)).ConfigureAwait(false); key.ETag = batchOperation.KeyETag; - if (logger.IsEnabled(LogLevel.Trace)) - logger.LogTrace("{PartitionKey}.{RowKey} Delete {TransactionId}", partition, states[i].Value.RowKey, states[i].Value.TransactionId); + LogTraceDeleteTransaction(partition, states[i].Value.RowKey, states[i].Value.TransactionId); } states.RemoveRange(0, pos); } await batchOperation.Flush().ConfigureAwait(false); - if (logger.IsEnabled(LogLevel.Debug)) - logger.LogDebug("{PartitionKey} Stored v{CommittedSequenceId} eTag={ETag}", partition, this.key.CommittedSequenceId, key.ETag); + LogDebugStoredETag(partition, this.key.CommittedSequenceId, key.ETag); return key.ETag.ToString(); } @@ -341,7 +331,7 @@ public async Task Flush() { for (int i = 0; i < batchOperation.Count; i++) { - logger.LogTrace("{PartitionKey}.{RowKey} batch-op ok {BatchCount}", batchOperation[i].Entity.PartitionKey, batchOperation[i].Entity.RowKey, i); + LogTraceBatchOpOk(logger, batchOperation[i].Entity.PartitionKey, batchOperation[i].Entity.RowKey, i); } } @@ -354,16 +344,98 @@ public async Task Flush() { for (int i = 0; i < batchOperation.Count; i++) { - logger.LogTrace("{PartitionKey}.{RowKey} batch-op failed {BatchCount}", batchOperation[i].Entity.PartitionKey, batchOperation[i].Entity.RowKey, i); + LogTraceBatchOpFailed(logger, batchOperation[i].Entity.PartitionKey, batchOperation[i].Entity.RowKey, i); } } - this.logger.LogError(ex, "Transactional state store failed."); + LogErrorTransactionalStateStoreFailed(logger, ex); throw; } } } } + [LoggerMessage( + Level = LogLevel.Debug, + Message = "{Partition} Loaded v0, fresh" + )] + private partial void LogDebugLoadedV0Fresh(string partition); + + [LoggerMessage( + Level = LogLevel.Critical, + Message = "{Partition} {Error}" + )] + private partial void LogCriticalPartitionError(string partition, string error); + + private readonly struct StatesLogRecord(List> states) + { + public override string ToString() => string.Join(",", states.Select(s => s.Key.ToString("x16"))); + } + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "{PartitionKey} Loaded v{CommittedSequenceId} rows={Data}" + )] + private partial void LogDebugLoadedPartitionKeyRows(string partitionKey, long committedSequenceId, StatesLogRecord data); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Transactional state load failed" + )] + private partial void LogErrorTransactionalStateLoadFailed(Exception ex); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "{PartitionKey}.{RowKey} Delete {TransactionId}" + )] + private partial void LogTraceDeleteTransaction(string partitionKey, string rowKey, string transactionId); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "{PartitionKey}.{RowKey} Update {TransactionId}" + )] + private partial void LogTraceUpdateTransaction(string partitionKey, string rowKey, string transactionId); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "{PartitionKey}.{RowKey} Insert {TransactionId}" + )] + private partial void LogTraceInsertTransaction(string partitionKey, string rowKey, string transactionId); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "{PartitionKey}.{RowKey} Insert. v{CommittedSequenceId}, {CommitRecordsCount}c" + )] + private partial void LogTraceInsertWithCount(string partitionKey, string rowKey, long committedSequenceId, int commitRecordsCount); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "{PartitionKey}.{RowKey} Update. v{CommittedSequenceId}, {CommitRecordsCount}c" + )] + private partial void LogTraceUpdateWithCount(string partitionKey, string rowKey, long committedSequenceId, int commitRecordsCount); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "{PartitionKey} Stored v{CommittedSequenceId} eTag={ETag}" + )] + private partial void LogDebugStoredETag(string partitionKey, long committedSequenceId, ETag eTag); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "{PartitionKey}.{RowKey} batch-op ok {BatchCount}" + )] + private static partial void LogTraceBatchOpOk(ILogger logger, string partitionKey, string rowKey, int batchCount); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "{PartitionKey}.{RowKey} batch-op failed {BatchCount}" + )] + private static partial void LogTraceBatchOpFailed(ILogger logger, string partitionKey, string rowKey, int batchCount); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Transactional state store failed." + )] + private static partial void LogErrorTransactionalStateStoreFailed(ILogger logger, Exception ex); } } diff --git a/src/Azure/Shared/Storage/AzureTableDataManager.cs b/src/Azure/Shared/Storage/AzureTableDataManager.cs index 0d37cf173d0..f4a92020c14 100644 --- a/src/Azure/Shared/Storage/AzureTableDataManager.cs +++ b/src/Azure/Shared/Storage/AzureTableDataManager.cs @@ -38,7 +38,7 @@ namespace Orleans.GrainDirectory.AzureStorage /// Utility class to encapsulate row-based access to Azure table storage. /// /// Table data entry used by this table / manager. - internal class AzureTableDataManager where T : class, ITableEntity + internal partial class AzureTableDataManager where T : class, ITableEntity { private readonly AzureStorageOperationOptions options; @@ -84,22 +84,17 @@ public async Task InitTableAsync() var tableItem = await table.CreateIfNotExistsAsync(); var didCreate = tableItem is not null; - Logger.LogInformation((int)Utilities.ErrorCode.AzureTable_01, "{Action} Azure storage table {TableName}", (didCreate ? "Created" : "Attached to"), TableName); - + LogInfoTableCreation(Logger, didCreate ? "Created" : "Attached to", TableName); Table = table; } catch (TimeoutException te) { - Logger.LogError( - (int)Utilities.ErrorCode.AzureTable_TableNotCreated, - te, - "Unable to create or connect to the Azure table in {CreationTimeout}", - StoragePolicyOptions.CreationTimeout); + LogErrorTableCreationInTimeout(Logger, te, StoragePolicyOptions.CreationTimeout); throw new OrleansException($"Unable to create or connect to the Azure table in {StoragePolicyOptions.CreationTimeout}", te); } catch (Exception exc) { - Logger.LogError((int)Utilities.ErrorCode.AzureTable_02, exc, "Could not initialize connection to storage table {TableName}", TableName); + LogErrorTableCreation(Logger, exc, TableName); throw; } finally @@ -123,12 +118,12 @@ public async Task DeleteTableAsync() var response = await tableCreationClient.DeleteTableAsync(TableName); if (response.Status == 204) { - Logger.LogInformation((int)Utilities.ErrorCode.AzureTable_03, "Deleted Azure storage table {TableName}", TableName); + LogInfoTableDeletion(Logger, TableName); } } catch (Exception exc) { - Logger.LogError((int)Utilities.ErrorCode.AzureTable_04, exc, "Could not delete storage table {TableName}", TableName); + LogErrorTableDeletion(Logger, exc, TableName); throw; } finally @@ -161,8 +156,7 @@ public async Task CreateTableEntryAsync(T data) const string operation = "CreateTableEntry"; var startTime = DateTime.UtcNow; - if (Logger.IsEnabled(LogLevel.Trace)) Logger.LogTrace("Creating {TableName} table entry: {Data}", TableName, data); - + LogTraceTableEntryCreation(Logger, TableName, data); try { try @@ -192,8 +186,7 @@ public async Task UpsertTableEntryAsync(T data) { const string operation = "UpsertTableEntry"; var startTime = DateTime.UtcNow; - if (Logger.IsEnabled(LogLevel.Trace)) Logger.LogTrace("{Operation} entry {Data} into table {TableName}", operation, data, TableName); - + LogTraceTableEntry(Logger, operation, data, TableName); try { try @@ -203,8 +196,7 @@ public async Task UpsertTableEntryAsync(T data) } catch (Exception exc) { - Logger.LogWarning((int)Utilities.ErrorCode.AzureTable_06, exc, - "Intermediate error upserting entry {Data} to the table {TableName}", data == null ? "null" : data.ToString(), TableName); + LogWarningUpsertTableEntry(Logger, exc, data, TableName); throw; } } @@ -223,8 +215,7 @@ public async Task UpsertTableEntryAsync(T data) { const string operation = "InsertTableEntry"; var startTime = DateTime.UtcNow; - if (Logger.IsEnabled(LogLevel.Trace)) Logger.LogTrace("{Operation} entry {Data} into table {TableName}", operation, data, TableName); - + LogTraceTableEntry(Logger, operation, data, TableName); try { try @@ -238,8 +229,7 @@ public async Task UpsertTableEntryAsync(T data) } catch (Exception exc) { - Logger.LogWarning((int)Utilities.ErrorCode.AzureTable_06, exc, - "Intermediate error inserting entry {Data} to the table {TableName}", data == null ? "null" : data.ToString(), TableName); + LogWarningInsertTableEntry(Logger, exc, data, TableName); throw; } } @@ -267,11 +257,9 @@ internal async Task MergeTableEntryAsync(T data, ETag eTag) { const string operation = "MergeTableEntry"; var startTime = DateTime.UtcNow; - if (Logger.IsEnabled(LogLevel.Trace)) Logger.LogTrace("{Operation} entry {Data} into table {TableName}", operation, data, TableName); - + LogTraceTableEntry(Logger, operation, data, TableName); try { - try { // Merge requires an ETag (which may be the '*' wildcard). @@ -281,8 +269,7 @@ internal async Task MergeTableEntryAsync(T data, ETag eTag) } catch (Exception exc) { - Logger.LogWarning((int)Utilities.ErrorCode.AzureTable_07, exc, - "Intermediate error merging entry {Data} to the table {TableName}", data == null ? "null" : data.ToString(), TableName); + LogWarningMergeTableEntry(Logger, exc, data, TableName); throw; } } @@ -312,7 +299,7 @@ public async Task UpdateTableEntryAsync(T data, ETag dataEtag) { const string operation = "UpdateTableEntryAsync"; var startTime = DateTime.UtcNow; - if (Logger.IsEnabled(LogLevel.Trace)) Logger.LogTrace("{Operation} entry {Data} into table {TableName}", operation, data, TableName); + LogTraceTableEntry(Logger, operation, data, TableName); try { @@ -356,12 +343,10 @@ public async Task DeleteTableEntryAsync(T data, ETag eTag) { const string operation = "DeleteTableEntryAsync"; var startTime = DateTime.UtcNow; - if (Logger.IsEnabled(LogLevel.Trace)) Logger.LogTrace("{Operation} entry {Data} table {TableName}", operation, data, TableName); - + LogTraceTableEntry(Logger, operation, data, TableName); try { data.ETag = eTag; - try { var response = await Table.DeleteEntityAsync(data.PartitionKey, data.RowKey, data.ETag); @@ -372,8 +357,7 @@ public async Task DeleteTableEntryAsync(T data, ETag eTag) } catch (Exception exc) { - Logger.LogWarning((int)Utilities.ErrorCode.AzureTable_08, exc, - "Intermediate error deleting entry {Data} from the table {TableName}.", data, TableName); + LogWarningDeleteTableEntry(Logger, exc, data, TableName); throw; } } @@ -393,8 +377,7 @@ public async Task DeleteTableEntryAsync(T data, ETag eTag) { const string operation = "ReadSingleTableEntryAsync"; var startTime = DateTime.UtcNow; - if (Logger.IsEnabled(LogLevel.Trace)) Logger.LogTrace("{Operation} table {TableName} partitionKey {PartitionKey} rowKey {RowKey}", operation, TableName, partitionKey, rowKey); - + LogTraceTableOperation(Logger, operation, TableName, partitionKey, rowKey); try { try @@ -414,7 +397,7 @@ public async Task DeleteTableEntryAsync(T data, ETag eTag) } } - if (Logger.IsEnabled(LogLevel.Debug)) Logger.LogDebug("Could not find table entry for PartitionKey={PartitionKey} RowKey={RowKey}", partitionKey, rowKey); + LogDebugTableEntryNotFound(Logger, partitionKey, rowKey); return (default, default); // No data } finally @@ -455,7 +438,7 @@ public async Task DeleteTableEntriesAsync(List<(T Entity, string ETag)> collecti { const string operation = "DeleteTableEntries"; var startTime = DateTime.UtcNow; - if (Logger.IsEnabled(LogLevel.Trace)) Logger.LogTrace("{Operation} entries: {Data} table {TableName}", operation, Utils.EnumerableToString(collection), TableName); + LogTraceTableEntries(Logger, operation, new(collection), TableName); if (collection == null) throw new ArgumentNullException(nameof(collection)); @@ -475,8 +458,8 @@ public async Task DeleteTableEntriesAsync(List<(T Entity, string ETag)> collecti var entityBatch = new List(); foreach (var tuple in collection) { - T item = tuple.Item1; - item.ETag = new ETag(tuple.Item2); + T item = tuple.Entity; + item.ETag = new ETag(tuple.ETag); entityBatch.Add(new TableTransactionAction(TableTransactionActionType.Delete, item, item.ETag)); } @@ -486,8 +469,7 @@ public async Task DeleteTableEntriesAsync(List<(T Entity, string ETag)> collecti } catch (Exception exc) { - Logger.LogWarning((int)Utilities.ErrorCode.AzureTable_08, exc, - "Intermediate error deleting entries {Data} from the table {TableName}.", Utils.EnumerableToString(collection), TableName); + LogWarningDeleteTableEntries(Logger, exc, new(collection), TableName); throw; } } @@ -509,7 +491,6 @@ public async Task DeleteTableEntriesAsync(List<(T Entity, string ETag)> collecti try { - try { async Task> executeQueryHandleContinuations() @@ -545,7 +526,7 @@ public async Task DeleteTableEntriesAsync(List<(T Entity, string ETag)> collecti // Out of retries... if (!AzureTableUtils.TableStorageDataNotFound(exc)) { - Logger.LogWarning((int)Utilities.ErrorCode.AzureTable_09, exc, "Failed to read Azure Storage table {TableName}", TableName); + LogWarningReadTable(Logger, exc, TableName); } throw new OrleansException($"Failed to read Azure Storage table {TableName}", exc); @@ -579,11 +560,9 @@ public async Task BulkInsertTableEntries(IReadOnlyCollection collection) } var startTime = DateTime.UtcNow; - if (Logger.IsEnabled(LogLevel.Trace)) Logger.LogTrace("{Operation} {Count} entries table {TableName}", operation, collection.Count, TableName); - + LogTraceTableEntriesCount(Logger, operation, collection.Count, TableName); try { - var entityBatch = new List(collection.Count); foreach (T entry in collection) { @@ -596,8 +575,7 @@ public async Task BulkInsertTableEntries(IReadOnlyCollection collection) } catch (Exception exc) { - Logger.LogWarning((int)Utilities.ErrorCode.AzureTable_37, exc, - "Intermediate error bulk inserting {Count} entries in the table {TableName}", collection.Count, TableName); + LogWarningBulkInsertTableEntries(Logger, exc, collection.Count, TableName); } } finally @@ -609,11 +587,10 @@ public async Task BulkInsertTableEntries(IReadOnlyCollection collection) internal async Task<(string, string)> InsertTwoTableEntriesConditionallyAsync(T data1, T data2, string data2Etag) { const string operation = "InsertTableEntryConditionally"; - string data2Str = (data2 == null ? "null" : data2.ToString()); + string data2Str = data2 == null ? "null" : data2.ToString(); var startTime = DateTime.UtcNow; - if (Logger.IsEnabled(LogLevel.Trace)) Logger.LogTrace("{Operation} data1 {Data1} data2 {Data2} table {TableName}", operation, data1, data2Str, TableName); - + LogTraceTableEntries(Logger, operation, data1, data2Str, TableName); try { try @@ -647,9 +624,9 @@ public async Task BulkInsertTableEntries(IReadOnlyCollection collection) internal async Task<(string, string)> UpdateTwoTableEntriesConditionallyAsync(T data1, string data1Etag, T data2, string data2Etag) { const string operation = "UpdateTableEntryConditionally"; - string data2Str = (data2 == null ? "null" : data2.ToString()); + string data2Str = data2 == null ? "null" : data2.ToString(); var startTime = DateTime.UtcNow; - if (Logger.IsEnabled(LogLevel.Trace)) Logger.LogTrace("{Operation} data1 {Data1} data2 {Data2} table {TableName}", operation, data1, data2Str, TableName); + LogTraceTableEntries(Logger, operation, data1, data2Str, TableName); try { @@ -694,7 +671,7 @@ private async ValueTask GetCloudTableCreationClientAsync() } catch (Exception exc) { - Logger.LogError((int)Utilities.ErrorCode.AzureTable_18, exc, "Error creating TableServiceClient."); + LogErrorTableServiceClientCreation(Logger, exc); throw; } } @@ -705,14 +682,11 @@ private void CheckAlertWriteError(string operation, object data1, string data2, if (AzureTableUtils.EvaluateException(exc, out httpStatusCode, out _) && AzureTableUtils.IsContentionError(httpStatusCode)) { // log at Verbose, since failure on conditional is not not an error. Will analyze and warn later, if required. - if (Logger.IsEnabled(LogLevel.Debug)) Logger.LogDebug((int)Utilities.ErrorCode.AzureTable_13, exc, - "Intermediate Azure table write error {Operation} to table {TableName} data1 {Data1} data2 {Data2}", operation, TableName, (data1 ?? "null"), (data2 ?? "null")); - + LogWarningTableWrite(Logger, operation, TableName, data1 ?? "null", data2 ?? "null"); } else { - Logger.LogError((int)Utilities.ErrorCode.AzureTable_14, exc, - "Azure table access write error {Operation} to table {TableName} entry {Data1}", operation, TableName, data1); + LogErrorTableWrite(Logger, exc, operation, TableName, data1); } } @@ -721,9 +695,167 @@ private void CheckAlertSlowAccess(DateTime startOperation, string operation) var timeSpan = DateTime.UtcNow - startOperation; if (timeSpan > this.StoragePolicyOptions.OperationTimeout) { - Logger.LogWarning((int)Utilities.ErrorCode.AzureTable_15, "Slow access to Azure Table {TableName} for {Operation}, which took {Duration}", TableName, operation, timeSpan); + LogWarningSlowAccess(Logger, operation, TableName, timeSpan); } } + + [LoggerMessage( + Level = LogLevel.Information, + EventId = (int)Utilities.ErrorCode.AzureTable_01, + Message = "{Action} Azure storage table {TableName}" + )] + private static partial void LogInfoTableCreation(ILogger logger, string action, string tableName); + + [LoggerMessage( + Level = LogLevel.Error, + EventId = (int)Utilities.ErrorCode.AzureTable_TableNotCreated, + Message = "Unable to create or connect to the Azure table in {CreationTimeout}" + )] + private static partial void LogErrorTableCreationInTimeout(ILogger logger, TimeoutException exception, TimeSpan creationTimeout); + + [LoggerMessage( + Level = LogLevel.Error, + EventId = (int)Utilities.ErrorCode.AzureTable_02, + Message = "Could not initialize connection to storage table {TableName}" + )] + private static partial void LogErrorTableCreation(ILogger logger, Exception exception, string tableName); + + [LoggerMessage( + Level = LogLevel.Information, + EventId = (int)Utilities.ErrorCode.AzureTable_03, + Message = "Deleted Azure storage table {TableName}" + )] + private static partial void LogInfoTableDeletion(ILogger logger, string tableName); + + [LoggerMessage( + Level = LogLevel.Error, + EventId = (int)Utilities.ErrorCode.AzureTable_04, + Message = "Could not delete storage table {TableName}" + )] + private static partial void LogErrorTableDeletion(ILogger logger, Exception exception, string tableName); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "Creating {TableName} table entry: {Data}" + )] + private static partial void LogTraceTableEntryCreation(ILogger logger, string tableName, T data); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "{Operation} entry {Data} into table {TableName}" + )] + private static partial void LogTraceTableEntry(ILogger logger, string operation, T data, string tableName); + + [LoggerMessage( + Level = LogLevel.Warning, + EventId = (int)Utilities.ErrorCode.AzureTable_06, + Message = "Intermediate error upserting entry {Data} to the table {TableName}" + )] + private static partial void LogWarningUpsertTableEntry(ILogger logger, Exception exception, T data, string tableName); + + [LoggerMessage( + Level = LogLevel.Warning, + EventId = (int)Utilities.ErrorCode.AzureTable_06, + Message = "Intermediate error inserting entry {Data} to the table {TableName}" + )] + private static partial void LogWarningInsertTableEntry(ILogger logger, Exception exception, T data, string tableName); + + [LoggerMessage( + Level = LogLevel.Warning, + EventId = (int)Utilities.ErrorCode.AzureTable_07, + Message = "Intermediate error merging entry {Data} to the table {TableName}" + )] + private static partial void LogWarningMergeTableEntry(ILogger logger, Exception exception, T data, string tableName); + + [LoggerMessage( + Level = LogLevel.Warning, + EventId = (int)Utilities.ErrorCode.AzureTable_08, + Message = "Intermediate error deleting entry {Data} from the table {TableName}." + )] + private static partial void LogWarningDeleteTableEntry(ILogger logger, Exception exception, T data, string tableName); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "{Operation} table {TableName} partitionKey {PartitionKey} rowKey {RowKey}" + )] + private static partial void LogTraceTableOperation(ILogger logger, string operation, string tableName, string partitionKey, string rowKey); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Could not find table entry for PartitionKey={PartitionKey} RowKey={RowKey}" + )] + private static partial void LogDebugTableEntryNotFound(ILogger logger, string partitionKey, string rowKey); + + private readonly struct CollectionLogEntry(List<(T Entity, string ETag)> collection) + { + public override string ToString() => Utils.EnumerableToString(collection); + } + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "{Operation} entries: {Data} table {TableName}" + )] + private static partial void LogTraceTableEntries(ILogger logger, string operation, CollectionLogEntry data, string tableName); + + [LoggerMessage( + Level = LogLevel.Warning, + EventId = (int)Utilities.ErrorCode.AzureTable_08, + Message = "Intermediate error deleting entries {Data} from the table {TableName}." + )] + private static partial void LogWarningDeleteTableEntries(ILogger logger, Exception exception, CollectionLogEntry data, string tableName); + + [LoggerMessage( + Level = LogLevel.Warning, + EventId = (int)Utilities.ErrorCode.AzureTable_09, + Message = "Failed to read Azure Storage table {TableName}" + )] + private static partial void LogWarningReadTable(ILogger logger, Exception exception, string tableName); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "{Operation} {Count} entries table {TableName}" + )] + private static partial void LogTraceTableEntriesCount(ILogger logger, string operation, int count, string tableName); + + [LoggerMessage( + Level = LogLevel.Warning, + EventId = (int)Utilities.ErrorCode.AzureTable_37, + Message = "Intermediate error bulk inserting {Count} entries in the table {TableName}" + )] + private static partial void LogWarningBulkInsertTableEntries(ILogger logger, Exception exception, int count, string tableName); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "{Operation} data1 {Data1} data2 {Data2} table {TableName}" + )] + private static partial void LogTraceTableEntries(ILogger logger, string operation, T data1, string data2, string tableName); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error creating TableServiceClient." + )] + private static partial void LogErrorTableServiceClientCreation(ILogger logger, Exception exception); + + [LoggerMessage( + Level = LogLevel.Debug, + EventId = (int)Utilities.ErrorCode.AzureTable_13, + Message = "Intermediate Azure table write error {Operation} to table {TableName} data1 {Data1} data2 {Data2}" + )] + private static partial void LogWarningTableWrite(ILogger logger, string operation, string tableName, object data1, object data2); + + [LoggerMessage( + Level = LogLevel.Error, + EventId = (int)Utilities.ErrorCode.AzureTable_14, + Message = "Azure table access write error {Operation} to table {TableName} entry {Data1}" + )] + private static partial void LogErrorTableWrite(ILogger logger, Exception exception, string operation, string tableName, object data1); + + [LoggerMessage( + Level = LogLevel.Warning, + EventId = (int)Utilities.ErrorCode.AzureTable_15, + Message = "Slow access to Azure Table {TableName} for {Operation}, which took {Duration}" + )] + private static partial void LogWarningSlowAccess(ILogger logger, string tableName, string operation, TimeSpan duration); } internal static class TableDataManagerInternalExtensions diff --git a/src/Azure/Shared/Storage/AzureTableUtils.cs b/src/Azure/Shared/Storage/AzureTableUtils.cs index d8af393a949..5ac65163f1a 100644 --- a/src/Azure/Shared/Storage/AzureTableUtils.cs +++ b/src/Azure/Shared/Storage/AzureTableUtils.cs @@ -228,51 +228,26 @@ internal static bool AnalyzeReadException(Exception exc, int iteration, string t if (we != null) { isLastErrorRetriable = true; - var statusCode = we.Status; - logger.LogWarning((int)Utilities.ErrorCode.AzureTable_10, - exc, - "Intermediate issue reading Azure storage table {TableName}: HTTP status code={StatusCode}", - tableName, - statusCode); + LogWarningIntermediateIssue(logger, exc, tableName, we.Status); } else { - HttpStatusCode httpStatusCode; - string restStatus; - if (EvaluateException(exc, out httpStatusCode, out restStatus, true)) + if (EvaluateException(exc, out var httpStatusCode, out var restStatus, true)) { - if (TableErrorCode.ResourceNotFound.ToString().Equals(restStatus)) + if (nameof(TableErrorCode.ResourceNotFound).Equals(restStatus)) { - if (logger.IsEnabled(LogLevel.Debug)) logger.LogDebug((int)Utilities.ErrorCode.AzureTable_DataNotFound, - exc, - "DataNotFound reading Azure storage table {TableName}:{Retry} HTTP status code={StatusCode} REST status code={RESTStatusCode}", - tableName, - iteration == 0 ? string.Empty : (" Repeat=" + iteration), - httpStatusCode, - restStatus); - + LogDebugDataNotFound(logger, exc, tableName, iteration == 0 ? string.Empty : (" Repeat=" + iteration), httpStatusCode, restStatus); isLastErrorRetriable = false; } else { isLastErrorRetriable = IsRetriableHttpError(httpStatusCode, restStatus); - - logger.LogWarning((int)Utilities.ErrorCode.AzureTable_11, - exc, - "Intermediate issue reading Azure storage table {TableName}:{Retry} IsRetriable={IsLastErrorRetriable} HTTP status code={StatusCode} REST status code={RestStatusCode}", - tableName, - iteration == 0 ? "" : (" Repeat=" + iteration), - isLastErrorRetriable, - httpStatusCode, - restStatus); + LogWarningIntermediateIssueWithRestStatusCode(logger, exc, tableName, iteration == 0 ? "" : (" Repeat=" + iteration), isLastErrorRetriable, httpStatusCode, restStatus); } } else { - logger.LogError((int)Utilities.ErrorCode.AzureTable_12, - exc, - "Unexpected issue reading Azure storage table {TableName}", - tableName); + LogErrorUnexpectedIssue(logger, exc, tableName); isLastErrorRetriable = false; } } @@ -298,5 +273,33 @@ internal static string RangeQuery(string partitionKey, string minRowKey, string { return TableClient.CreateQueryFilter($"((PartitionKey eq {partitionKey}) and (RowKey ge {minRowKey})) and (RowKey le {maxRowKey})"); } + + [LoggerMessage( + Level = LogLevel.Warning, + EventId = (int)Utilities.ErrorCode.AzureTable_10, + Message = "Intermediate issue reading Azure storage table {TableName}: HTTP status code={StatusCode}" + )] + private static partial void LogWarningIntermediateIssue(ILogger logger, Exception exception, string tableName, WebExceptionStatus statusCode); + + [LoggerMessage( + Level = LogLevel.Debug, + EventId = (int)Utilities.ErrorCode.AzureTable_DataNotFound, + Message = "DataNotFound reading Azure storage table {TableName}:{Retry} HTTP status code={StatusCode} REST status code={RESTStatusCode}" + )] + private static partial void LogDebugDataNotFound(ILogger logger, Exception exception, string tableName, string retry, HttpStatusCode statusCode, string restStatusCode); + + [LoggerMessage( + Level = LogLevel.Warning, + EventId = (int)Utilities.ErrorCode.AzureTable_11, + Message = "Intermediate issue reading Azure storage table {TableName}:{Retry} IsRetriable={IsLastErrorRetriable} HTTP status code={StatusCode} REST status code={RestStatusCode}" + )] + private static partial void LogWarningIntermediateIssueWithRestStatusCode(ILogger logger, Exception exception, string tableName, string retry, bool isLastErrorRetriable, HttpStatusCode statusCode, string restStatusCode); + + [LoggerMessage( + Level = LogLevel.Error, + EventId = (int)Utilities.ErrorCode.AzureTable_12, + Message = "Unexpected issue reading Azure storage table {TableName}" + )] + private static partial void LogErrorUnexpectedIssue(ILogger logger, Exception exception, string tableName); } } diff --git a/src/Orleans.Runtime/Catalog/ActivationData.cs b/src/Orleans.Runtime/Catalog/ActivationData.cs index 1cd13d1a47d..15f5aa4a4eb 100644 --- a/src/Orleans.Runtime/Catalog/ActivationData.cs +++ b/src/Orleans.Runtime/Catalog/ActivationData.cs @@ -528,7 +528,7 @@ private async Task StartMigratingAsync(Dictionary? requestContex } catch (Exception exception) { - LogErrorSelectingMigrationDestination(_shared.Logger, GrainId, exception); + LogErrorSelectingMigrationDestination(_shared.Logger, exception, GrainId); return; } } @@ -2203,7 +2203,7 @@ private class MigrateWorkItem(ActivationData activation, Dictionary