Moving logging to defined methods in DiagnosticEventsTableStorageRepository. Disabling service when the client is not authorized to use the table storage service.

Author: cjaliaga

src/WebJobs.Script.WebHost/Diagnostics/DiagnosticEventTableStorageRepository.Log.cs

@@ -0,0 +1,74 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the MIT License. See License.txt in the project root for license information.
+
+using System;
+using Microsoft.Extensions.Logging;
+
+namespace Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics
+{
+    public partial class DiagnosticEventTableStorageRepository
+    {
+        private static class Logger
+        {
+            private static readonly Action<ILogger, Exception> _serviceDisabledFailedToCreateClient =
+                LoggerMessage.Define(LogLevel.Warning, new EventId(1, nameof(ServiceDisabledFailedToCreateClient)), "An error occurred initializing the Table Storage Client. We are unable to record diagnostic events, so the diagnostic logging service is being stopped.");
+
+            private static readonly Action<ILogger, Exception> _serviceDisabledUnauthorizedClient =
+                LoggerMessage.Define(LogLevel.Warning, new EventId(2, nameof(ServiceDisabledUnauthorizedClient)), "The Table Storage Client is not authorized to access the table storage account. We are unable to record diagnostic events, so the diagnostic logging service is being stopped.");
+
+            private static readonly Action<ILogger, string, Exception> _purgingDiagnosticEvents =
+                LoggerMessage.Define<string>(LogLevel.Debug, new EventId(3, nameof(PurgingDiagnosticEvents)), "Purging diagnostic events with versions older than '{currentEventVersion}'.");
+
+            private static readonly Action<ILogger, string, Exception> _deletingTableWithoutEventVersion =
+                LoggerMessage.Define<string>(LogLevel.Debug, new EventId(4, nameof(DeletingTableWithoutEventVersion)), "Deleting table '{tableName}' as it contains records without an EventVersion.");
+
+            private static readonly Action<ILogger, string, Exception> _deletingTableWithOutdatedEventVersion =
+                LoggerMessage.Define<string>(LogLevel.Debug, new EventId(5, nameof(DeletingTableWithOutdatedEventVersion)), "Deleting table '{tableName}' as it contains records with an outdated EventVersion.");
+
+            private static readonly Action<ILogger, Exception> _errorPurgingDiagnosticEventVersions =
+                LoggerMessage.Define(LogLevel.Error, new EventId(6, nameof(ErrorPurgingDiagnosticEventVersions)), "Error occurred when attempting to purge previous diagnostic event versions.");
+
+            private static readonly Action<ILogger, Exception> _unableToGetTableReference =
+                LoggerMessage.Define(LogLevel.Error, new EventId(7, nameof(UnableToGetTableReference)), "Unable to get table reference. Aborting write operation.");
+
+            private static readonly Action<ILogger, Exception> _unableToGetTableReferenceOrCreateTable =
+                LoggerMessage.Define(LogLevel.Error, new EventId(8, nameof(UnableToGetTableReferenceOrCreateTable)), "Unable to get table reference or create table. Aborting write operation.");
+
+            private static readonly Action<ILogger, Exception> _unableToWriteDiagnosticEvents =
+                LoggerMessage.Define(LogLevel.Error, new EventId(9, nameof(UnableToWriteDiagnosticEvents)), "Unable to write diagnostic events to table storage.");
+
+            private static readonly Action<ILogger, Exception> _primaryHostStateProviderNotAvailable =
+                LoggerMessage.Define(LogLevel.Debug, new EventId(10, nameof(PrimaryHostStateProviderNotAvailable)), "PrimaryHostStateProvider is not available. Skipping the check for primary host.");
+
+            private static readonly Action<ILogger, Exception> _stoppingFlushLogsTimer =
+                LoggerMessage.Define(LogLevel.Information, new EventId(11, nameof(StoppingFlushLogsTimer)), "Stopping the flush logs timer.");
+
+            private static readonly Action<ILogger, Exception> _queueingBackgroundTablePurge =
+                LoggerMessage.Define(LogLevel.Debug, new EventId(12, nameof(QueueingBackgroundTablePurge)), "Queueing background table purge.");
+
+            public static void ServiceDisabledFailedToCreateClient(ILogger logger) => _serviceDisabledFailedToCreateClient(logger, null);
+
+            public static void ServiceDisabledUnauthorizedClient(ILogger logger, Exception exception) => _serviceDisabledUnauthorizedClient(logger, exception);
+
+            public static void PurgingDiagnosticEvents(ILogger logger, string currentEventVersion) => _purgingDiagnosticEvents(logger, currentEventVersion, null);
+
+            public static void DeletingTableWithoutEventVersion(ILogger logger, string tableName) => _deletingTableWithoutEventVersion(logger, tableName, null);
+
+            public static void DeletingTableWithOutdatedEventVersion(ILogger logger, string tableName) => _deletingTableWithOutdatedEventVersion(logger, tableName, null);
+
+            public static void ErrorPurgingDiagnosticEventVersions(ILogger<DiagnosticEventTableStorageRepository> logger, Exception exception) => _errorPurgingDiagnosticEventVersions(logger, exception);
+
+            public static void UnableToGetTableReference(ILogger logger) => _unableToGetTableReference(logger, null);
+
+            public static void UnableToGetTableReferenceOrCreateTable(ILogger logger, Exception exception) => _unableToGetTableReferenceOrCreateTable(logger, exception);
+
+            public static void UnableToWriteDiagnosticEvents(ILogger logger, Exception exception) => _unableToWriteDiagnosticEvents(logger, exception);
+
+            public static void PrimaryHostStateProviderNotAvailable(ILogger logger) => _primaryHostStateProviderNotAvailable(logger, null);
+
+            public static void StoppingFlushLogsTimer(ILogger logger) => _stoppingFlushLogsTimer(logger, null);
+
+            public static void QueueingBackgroundTablePurge(ILogger logger) => _queueingBackgroundTablePurge(logger, null);
+        }
+    }
+}

src/WebJobs.Script.WebHost/Diagnostics/DiagnosticEventTableStorageRepository.cs

@@ -7,6 +7,7 @@
 using System.Linq;
 using System.Threading;
 using System.Threading.Tasks;
+using Azure;
 using Azure.Data.Tables;
 using Microsoft.Azure.WebJobs.Host.Executors;
 using Microsoft.Azure.WebJobs.Hosting;
@@ -17,7 +18,7 @@
 
 namespace Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics
 {
-    public class DiagnosticEventTableStorageRepository : IDiagnosticEventRepository, IDisposable
+    public partial class DiagnosticEventTableStorageRepository : IDiagnosticEventRepository, IDisposable
     {
         internal const string TableNamePrefix = "AzureFunctionsDiagnosticEvents";
         private const int LogFlushInterval = 1000 * 60 * 10; // 10 minutes
@@ -59,11 +60,33 @@ internal TableServiceClient TableClient
         {
             get
             {
-                if (!_environment.IsPlaceholderModeEnabled() && _tableClient == null && !_azureTableStorageProvider.TryCreateHostingTableServiceClient(out _tableClient))
+                if (!_environment.IsPlaceholderModeEnabled() && _tableClient == null)
                 {
-                    _logger.LogWarning("An error occurred initializing the Table Storage Client. We are unable to record diagnostic events, so the diagnostic logging service is being stopped.");
-                    _isEnabled = false;
-                    StopTimer();
+                    if (!_azureTableStorageProvider.TryCreateHostingTableServiceClient(out _tableClient))
+                    {
+                        DisableService();
+                        Logger.ServiceDisabledFailedToCreateClient(_logger);
+                        return _tableClient;
+                    }
+
+                    try
+                    {
+                        // When using RBAC, we need "Storage Table Data Contributor" as we require to list, create and delete tables and query/insert/delete entities.
+                        // Testing permissions by listing tables and creating a test table.
+                        var testTable = _tableClient.GetTableClient($"{TableNamePrefix}Check");
+                        _ = TableStorageHelpers.TableExist(testTable, _tableClient);
+                        _ = testTable.CreateIfNotExists();
+                    }
+                    catch (RequestFailedException ex) when (ex.Status == 403)
+                    {
+                        DisableService();
+                        Logger.ServiceDisabledUnauthorizedClient(_logger, ex);
+                    }
+                    catch (Exception)
+                    {
+                        // Other exceptions might be due to conflict issues or other transient errors
+                        // which don't necessarily indicate a permissions problem
+                    }
                 }
 
                 return _tableClient;
@@ -84,6 +107,13 @@ internal string HostId
 
         internal ConcurrentDictionary<string, DiagnosticEvent> Events => _events;
 
+        private void DisableService()
+        {
+            _isEnabled = false;
+            StopTimer();
+            _events.Clear();
+        }
+
         internal TableClient GetDiagnosticEventsTable(DateTime? now = null)
         {
             if (TableClient != null)
@@ -114,7 +144,7 @@ protected internal virtual async void OnFlushLogs(object state)
 
         private async Task PurgePreviousEventVersions()
         {
-            _logger.LogDebug("Purging diagnostic events with versions older than '{currentEventVersion}'.", DiagnosticEvent.CurrentEventVersion);
+            Logger.PurgingDiagnosticEvents(_logger, DiagnosticEvent.CurrentEventVersion);
 
             bool tableDeleted = false;
 
@@ -133,7 +163,7 @@ await Utility.InvokeWithRetriesAsync(async () =>
                             // Delete table if it doesn't have records with EventVersion
                             if (string.IsNullOrEmpty(record.EventVersion) == true)
                             {
-                                _logger.LogDebug("Deleting table '{tableName}' as it contains records without an EventVersion.", table.Name);
+                                Logger.DeletingTableWithoutEventVersion(_logger, table.Name);
                                 await table.DeleteAsync();
                                 tableDeleted = true;
                                 break;
@@ -142,7 +172,7 @@ await Utility.InvokeWithRetriesAsync(async () =>
                             // If the table does have EventVersion, query if it is an outdated version
                             if (string.Compare(DiagnosticEvent.CurrentEventVersion, record.EventVersion, StringComparison.Ordinal) > 0)
                             {
-                                _logger.LogDebug("Deleting table '{tableName}' as it contains records with an outdated EventVersion.", table.Name);
+                                Logger.DeletingTableWithOutdatedEventVersion(_logger, table.Name);
                                 await table.DeleteAsync();
                                 tableDeleted = true;
                                 break;
@@ -154,7 +184,7 @@ await Utility.InvokeWithRetriesAsync(async () =>
                 }
                 catch (Exception ex)
                 {
-                    _logger.LogError(ex, "Error occurred when attempting to purge previous diagnostic event versions.");
+                    Logger.ErrorPurgingDiagnosticEventVersions(_logger, ex);
                 }
             }, maxRetries: 5, retryInterval: TimeSpan.FromSeconds(5));
 
@@ -170,7 +200,7 @@ internal virtual async Task FlushLogs(TableClient table = null)
             // TableClient is initialized lazily and it will stop the timer that schedules flush logs whenever it fails to initialize.
             // We need to check if the TableClient is null before proceeding. This helps when the first time the property is accessed is as part of the FlushLogs method.
             // We should not have any events stored pending to be written since WriteDiagnosticEvent will check for an initialized TableClient.
-            if (_environment.IsPlaceholderModeEnabled() || TableClient is null)
+            if (_environment.IsPlaceholderModeEnabled() || TableClient is null || !IsEnabled())
             {
                 return;
             }
@@ -186,21 +216,21 @@ internal virtual async Task FlushLogs(TableClient table = null)
 
                 if (table == null)
                 {
-                    _logger.LogError("Unable to get table reference. Aborting write operation.");
-                    StopTimer();
+                    Logger.UnableToGetTableReference(_logger);
+                    DisableService();
                     return;
                 }
 
                 bool tableCreated = await TableStorageHelpers.CreateIfNotExistsAsync(table, TableClient, TableCreationMaxRetryCount);
                 if (tableCreated)
                 {
-                    _logger.LogDebug("Queueing background table purge.");
+                    Logger.QueueingBackgroundTablePurge(_logger);
                     TableStorageHelpers.QueueBackgroundTablePurge(table, TableClient, TableNamePrefix, _logger);
                 }
             }
             catch (Exception ex)
             {
-                _logger.LogError(ex, "Unable to get table reference or create table. Aborting write operation.");
+                Logger.UnableToGetTableReferenceOrCreateTable(_logger, ex);
                 // Clearing the memory cache to avoid memory build up.
                 _events.Clear();
                 return;
@@ -234,7 +264,7 @@ internal async Task ExecuteBatchAsync(ConcurrentDictionary<string, DiagnosticEve
             }
             catch (Exception ex)
             {
-                _logger.LogError(ex, "Unable to write diagnostic events to table storage.");
+                Logger.UnableToWriteDiagnosticEvents(_logger, ex);
             }
         }
 
@@ -275,7 +305,7 @@ private bool IsPrimaryHost()
             var primaryHostStateProvider = _serviceProvider?.GetService<IPrimaryHostStateProvider>();
             if (primaryHostStateProvider is null)
             {
-                _logger.LogDebug("PrimaryHostStateProvider is not available. Skipping the check for primary host.");
+                Logger.PrimaryHostStateProviderNotAvailable(_logger);
                 return false;
             }
 
@@ -284,7 +314,7 @@ private bool IsPrimaryHost()
 
         private void StopTimer()
         {
-            _logger.LogInformation("Stopping the flush logs timer.");
+            Logger.StoppingFlushLogsTimer(_logger);
             _flushLogsTimer?.Change(Timeout.Infinite, Timeout.Infinite);
         }
 

src/WebJobs.Script.WebHost/Helpers/TableStorageHelpers.cs

@@ -96,6 +96,8 @@ internal static async Task<IEnumerable<TableClient>> ListOldTablesAsync(TableCli
 
         internal static async Task<IEnumerable<TableClient>> ListTablesAsync(TableServiceClient tableClient, string tableNamePrefix)
         {
+            ArgumentNullException.ThrowIfNull(tableClient, nameof(tableClient));
+
             // Azure.Data.Tables doesn't have a direct way to list tables with a prefix so we need to do it manually
             var givenValue = tableNamePrefix + "{";
             AsyncPageable<TableItem> tablesQuery = tableClient.QueryAsync(p => p.Name.CompareTo(tableNamePrefix) >= 0 && p.Name.CompareTo(givenValue) <= 0);
@@ -120,5 +122,17 @@ internal static async Task<bool> TableExistAsync(TableClient table, TableService
 
             return false;
         }
+
+        internal static bool TableExist(TableClient table, TableServiceClient tableClient)
+        {
+            var query = tableClient.Query(p => p.Name == table.Name);
+
+            foreach (var item in query)
+            {
+                return true;
+            }
+
+            return false;
+        }
     }
 }

test/WebJobs.Script.Tests.Integration/Diagnostics/DiagnosticEventTableStorageRepositoryTests.cs

@@ -164,7 +164,8 @@ public void GetDiagnosticEventsTable_LogsError_StorageConnectionStringIsNotPrese
             var cloudTable = repository.GetDiagnosticEventsTable(dateTime);
             Assert.Null(cloudTable);
             var messages = _loggerProvider.GetAllLogMessages();
-            Assert.Equal(messages[0].FormattedMessage, "An error occurred initializing the Table Storage Client. We are unable to record diagnostic events, so the diagnostic logging service is being stopped.");
+            var errorIntializingPresent = messages.Any(m => m.FormattedMessage.Contains( "An error occurred initializing the Table Storage Client. We are unable to record diagnostic events, so the diagnostic logging service is being stopped."));
+            Assert.True(errorIntializingPresent);
             Assert.False(repository.IsEnabled());
         }