Skip to content

Commit 655b8a6

Browse files
aishwaryabhaishwaryabh
authored
Reducing noise for metadata logging (#9464)
* adding logging change * specifying details of provider * removing extra * adding unit tests * addressing comments * comments * fixing build errors * fixing tests * comments
1 parent 927ffda commit 655b8a6

File tree

7 files changed

+86
-22
lines changed

7 files changed

+86
-22
lines changed

‎src/WebJobs.Script/Diagnostics/Extensions/LoggerExtension.cs‎

Lines changed: 14 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -121,15 +121,15 @@ internal static class LoggerExtension
121121
new EventId(325, nameof(ScriptStartUpLoadedExtension)),
122122
"Loaded extension '{startupExtensionName}' ({startupExtensionVersion})");
123123

124-
private static readonly Action<ILogger, Exception> _functionMetadataProviderReadingMetadata =
125-
LoggerMessage.Define(LogLevel.Information,
126-
new EventId(326, nameof(FunctionMetadataManagerLoadingFunctionsMetadata)),
127-
"Reading functions metadata");
124+
private static readonly Action<ILogger, string, Exception> _readingFunctionMetadataFromProvider =
125+
LoggerMessage.Define<string>(LogLevel.Information,
126+
new EventId(326, nameof(ReadingFunctionMetadataFromProvider)),
127+
"Reading functions metadata ({provider})");
128128

129-
private static readonly Action<ILogger, int, Exception> _functionMetadataProviderFunctionsFound =
130-
LoggerMessage.Define<int>(LogLevel.Information,
131-
new EventId(327, nameof(FunctionMetadataManagerFunctionsLoaded)),
132-
"{count} functions found");
129+
private static readonly Action<ILogger, int, string, Exception> _functionsReturnedByProvider =
130+
LoggerMessage.Define<int, string>(LogLevel.Information,
131+
new EventId(327, nameof(FunctionsReturnedByProvider)),
132+
"{count} functions found ({provider})");
133133

134134
private static readonly Action<ILogger, string, Guid, Exception> _customHandlerForwardingHttpTriggerInvocation =
135135
LoggerMessage.Define<string, Guid>(LogLevel.Debug,
@@ -280,19 +280,19 @@ public static void FunctionMetadataManagerLoadingFunctionsMetadata(this ILogger
280280
_functionMetadataManagerLoadingFunctionsMetadata(logger, null);
281281
}
282282

283-
public static void FunctionMetadataManagerFunctionsLoaded(this ILogger logger, int count)
283+
public static void ReadingFunctionMetadataFromProvider(this ILogger logger, string provider)
284284
{
285-
_functionMetadataManagerFunctionsLoaded(logger, count, null);
285+
_readingFunctionMetadataFromProvider(logger, provider, null);
286286
}
287287

288-
public static void FunctionMetadataProviderParsingFunctions(this ILogger logger)
288+
public static void FunctionMetadataManagerFunctionsLoaded(this ILogger logger, int count)
289289
{
290-
_functionMetadataProviderReadingMetadata(logger, null);
290+
_functionMetadataManagerFunctionsLoaded(logger, count, null);
291291
}
292292

293-
public static void FunctionMetadataProviderFunctionFound(this ILogger logger, int count)
293+
public static void FunctionsReturnedByProvider(this ILogger logger, int count, string provider)
294294
{
295-
_functionMetadataProviderFunctionsFound(logger, count, null);
295+
_functionsReturnedByProvider(logger, count, provider, null);
296296
}
297297

298298
public static void AutoRecoveringFileSystemWatcherFailureDetected(this ILogger logger, string errorMessage, string path)

‎src/WebJobs.Script/Host/FunctionMetadataManager.cs‎

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,7 @@ namespace Microsoft.Azure.WebJobs.Script
2222
public class FunctionMetadataManager : IFunctionMetadataManager
2323
{
2424
private const string _functionConfigurationErrorMessage = "Unable to determine the primary function script.Make sure atleast one script file is present.Try renaming your entry point script to 'run' or alternatively you can specify the name of the entry point script explicitly by adding a 'scriptFile' property to your function metadata.";
25+
private const string _metadataProviderName = "Custom";
2526
private readonly IServiceProvider _serviceProvider;
2627
private readonly ILoggerFactory _loggerFactory;
2728
private IFunctionMetadataProvider _functionMetadataProvider;
@@ -215,7 +216,7 @@ private void LoadCustomProviderFunctions(List<FunctionMetadata> functionMetadata
215216

216217
private void AddMetadataFromCustomProviders(IEnumerable<IFunctionProvider> functionProviders, List<FunctionMetadata> functionMetadataList)
217218
{
218-
_logger.FunctionMetadataProviderParsingFunctions();
219+
_logger.ReadingFunctionMetadataFromProvider(_metadataProviderName);
219220

220221
var functionProviderTasks = new List<Task<ImmutableArray<FunctionMetadata>>>();
221222
foreach (var functionProvider in functionProviders)
@@ -228,7 +229,7 @@ private void AddMetadataFromCustomProviders(IEnumerable<IFunctionProvider> funct
228229
// This is used to make sure no duplicates are registered
229230
var distinctFunctionNames = new HashSet<string>(functionMetadataList.Select(m => m.Name));
230231

231-
_logger.FunctionMetadataProviderFunctionFound(functionMetadataListArray.Length);
232+
_logger.FunctionsReturnedByProvider(functionMetadataListArray.Length, _metadataProviderName);
232233

233234
foreach (var metadataArray in functionMetadataListArray)
234235
{

‎src/WebJobs.Script/Host/HostFunctionMetadataProvider.cs‎

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -22,6 +22,7 @@ namespace Microsoft.Azure.WebJobs.Script
2222
{
2323
internal class HostFunctionMetadataProvider : IHostFunctionMetadataProvider
2424
{
25+
private const string _metadataProviderName = "Host";
2526
private readonly IOptionsMonitor<ScriptApplicationHostOptions> _applicationHostOptions;
2627
private readonly IMetricsLogger _metricsLogger;
2728
private readonly Dictionary<string, ICollection<string>> _functionErrors = new Dictionary<string, ICollection<string>>();
@@ -47,9 +48,9 @@ public async Task<ImmutableArray<FunctionMetadata>> GetFunctionMetadataAsync(IEn
4748

4849
if (_functions.IsDefaultOrEmpty || forceRefresh)
4950
{
50-
_logger.FunctionMetadataProviderParsingFunctions();
51+
_logger.ReadingFunctionMetadataFromProvider(_metadataProviderName);
5152
Collection<FunctionMetadata> functionMetadata = ReadFunctionsMetadata(workerConfigs);
52-
_logger.FunctionMetadataProviderFunctionFound(functionMetadata.Count);
53+
_logger.FunctionsReturnedByProvider(functionMetadata.Count, _metadataProviderName);
5354
_functions = functionMetadata.ToImmutableArray();
5455
}
5556

‎src/WebJobs.Script/Host/WorkerFunctionMetadataProvider.cs‎

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,7 @@ namespace Microsoft.Azure.WebJobs.Script
1919
{
2020
internal class WorkerFunctionMetadataProvider : IWorkerFunctionMetadataProvider
2121
{
22+
private const string _metadataProviderName = "Worker";
2223
private readonly Dictionary<string, ICollection<string>> _functionErrors = new Dictionary<string, ICollection<string>>();
2324
private readonly IOptionsMonitor<ScriptApplicationHostOptions> _scriptOptions;
2425
private readonly ILogger _logger;
@@ -50,7 +51,7 @@ public async Task<FunctionMetadataResult> GetFunctionMetadataAsync(IEnumerable<R
5051
_logger.LogInformation("Fetching metadata for workerRuntime: {workerRuntime}", _workerRuntime);
5152

5253
IEnumerable<FunctionMetadata> functions = new List<FunctionMetadata>();
53-
_logger.FunctionMetadataProviderParsingFunctions();
54+
_logger.ReadingFunctionMetadataFromProvider(_metadataProviderName);
5455

5556
if (_functions.IsDefaultOrEmpty || forceRefresh)
5657
{
@@ -102,7 +103,7 @@ public async Task<FunctionMetadataResult> GetFunctionMetadataAsync(IEnumerable<R
102103
}
103104

104105
_functions = functions.ToImmutableArray();
105-
_logger.FunctionMetadataProviderFunctionFound(_functions.IsDefault ? 0 : _functions.Count());
106+
_logger.FunctionsReturnedByProvider(_functions.IsDefault ? 0 : _functions.Count(), _metadataProviderName);
106107

107108
// Validate if the app has functions in legacy format and add in logs to inform about the mixed app
108109
_ = Task.Delay(TimeSpan.FromMinutes(1)).ContinueWith(t => ValidateFunctionAppFormat(_scriptOptions.CurrentValue.ScriptPath, _logger, _environment));

‎test/WebJobs.Script.Tests/FunctionMetadataManagerTests.cs‎

Lines changed: 15 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -12,9 +12,12 @@
1212
using Microsoft.Azure.WebJobs.Script.Workers.Http;
1313
using Microsoft.Azure.WebJobs.Script.Workers.Rpc;
1414
using Microsoft.Extensions.Hosting;
15+
using Microsoft.Extensions.Logging;
1516
using Microsoft.Extensions.Options;
17+
using Microsoft.WebJobs.Script.Tests;
1618
using Moq;
1719
using Xunit;
20+
using static Microsoft.Azure.AppService.Proxy.Common.Constants.WellKnownHttpHeaders;
1821

1922
namespace Microsoft.Azure.WebJobs.Script.Tests
2023
{
@@ -143,6 +146,9 @@ public void FunctionMetadataManager_GetsMetadata_FromFunctionProviders()
143146
var mockFunctionMetadataProvider = new Mock<IFunctionMetadataProvider>();
144147
var mockFunctionProvider = new Mock<IFunctionProvider>();
145148
var workerConfigs = TestHelpers.GetTestWorkerConfigs();
149+
var testLoggerProvider = new TestLoggerProvider();
150+
var loggerFactory = new LoggerFactory();
151+
loggerFactory.AddProvider(testLoggerProvider);
146152

147153
mockFunctionMetadataProvider.Setup(m => m.GetFunctionMetadataAsync(workerConfigs, SystemEnvironment.Instance, false)).Returns(Task.FromResult(new Collection<FunctionMetadata>().ToImmutableArray()));
148154
mockFunctionMetadataProvider.Setup(m => m.FunctionErrors).Returns(new Dictionary<string, ICollection<string>>().ToImmutableDictionary(kvp => kvp.Key, kvp => kvp.Value.ToImmutableArray()));
@@ -153,12 +159,20 @@ public void FunctionMetadataManager_GetsMetadata_FromFunctionProviders()
153159
mockFunctionProvider.Setup(m => m.FunctionErrors).Returns(mockFunctionErrors.ToImmutableDictionary());
154160

155161
FunctionMetadataManager testFunctionMetadataManager = TestFunctionMetadataManager.GetFunctionMetadataManager(new OptionsWrapper<ScriptJobHostOptions>(_scriptJobHostOptions),
156-
mockFunctionMetadataProvider.Object, new List<IFunctionProvider>() { mockFunctionProvider.Object }, new OptionsWrapper<HttpWorkerOptions>(_defaultHttpWorkerOptions), MockNullLoggerFactory.CreateLoggerFactory(), new TestOptionsMonitor<LanguageWorkerOptions>(TestHelpers.GetTestLanguageWorkerOptions()));
162+
mockFunctionMetadataProvider.Object, new List<IFunctionProvider>() { mockFunctionProvider.Object }, new OptionsWrapper<HttpWorkerOptions>(_defaultHttpWorkerOptions), loggerFactory, new TestOptionsMonitor<LanguageWorkerOptions>(TestHelpers.GetTestLanguageWorkerOptions()));
157163
testFunctionMetadataManager.LoadFunctionMetadata();
158164

159165
Assert.Equal(0, testFunctionMetadataManager.Errors.Count);
160166
Assert.Equal(1, testFunctionMetadataManager.GetFunctionMetadata(true).Length);
167+
var traces = testLoggerProvider.GetAllLogMessages();
161168
Assert.Equal("anotherFunction", testFunctionMetadataManager.GetFunctionMetadata(true).FirstOrDefault()?.Name);
169+
170+
// Assert logging traces print out as expected
171+
Assert.Equal(7, traces.Count);
172+
Assert.Equal(2, traces.Count(t => t.FormattedMessage.Contains("Reading functions metadata (Custom)")));
173+
Assert.Equal(2, traces.Count(t => t.FormattedMessage.Contains("1 functions found (Custom)")));
174+
Assert.Equal(1, traces.Count(t => t.FormattedMessage.Contains("1 functions loaded")));
175+
Assert.Equal(2, traces.Count(t => t.FormattedMessage.Contains("Loading functions metadata")));
162176
}
163177

164178
[Fact]

‎test/WebJobs.Script.Tests/HostFunctionMetadataProviderTests.cs‎

Lines changed: 13 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -10,7 +10,9 @@
1010
using Microsoft.Azure.WebJobs.Script.Description;
1111
using Microsoft.Azure.WebJobs.Script.Diagnostics;
1212
using Microsoft.Azure.WebJobs.Script.Workers.Rpc;
13+
using Microsoft.Extensions.Logging;
1314
using Microsoft.Extensions.Logging.Abstractions;
15+
using Microsoft.WebJobs.Script.Tests;
1416
using Moq;
1517
using Newtonsoft.Json.Linq;
1618
using Xunit;
@@ -31,14 +33,24 @@ public HostFunctionMetadataProviderTests()
3133
[Fact]
3234
public void ReadFunctionMetadata_Succeeds()
3335
{
36+
var testLoggerProvider = new TestLoggerProvider();
37+
var loggerFactory = new LoggerFactory();
38+
loggerFactory.AddProvider(testLoggerProvider);
39+
var logger = loggerFactory.CreateLogger<HostFunctionMetadataProvider>();
3440
string functionsPath = Path.Combine(Environment.CurrentDirectory, @"..", "..", "..", "..", "..", "sample", "node");
3541
_scriptApplicationHostOptions.ScriptPath = functionsPath;
3642
var optionsMonitor = TestHelpers.CreateOptionsMonitor(_scriptApplicationHostOptions);
37-
var metadataProvider = new HostFunctionMetadataProvider(optionsMonitor, NullLogger<HostFunctionMetadataProvider>.Instance, _testMetricsLogger, SystemEnvironment.Instance);
43+
var metadataProvider = new HostFunctionMetadataProvider(optionsMonitor, logger, _testMetricsLogger, SystemEnvironment.Instance);
3844
var workerConfigs = TestHelpers.GetTestWorkerConfigs();
3945

4046
Assert.Equal(18, metadataProvider.GetFunctionMetadataAsync(workerConfigs, SystemEnvironment.Instance, false).Result.Length);
47+
var traces = testLoggerProvider.GetAllLogMessages();
4148
Assert.True(AreRequiredMetricsEmitted(_testMetricsLogger));
49+
50+
// Assert that the logs contain the expected messages
51+
Assert.Equal(2, traces.Count);
52+
Assert.Equal("Reading functions metadata (Host)", traces[0].FormattedMessage);
53+
Assert.Equal("18 functions found (Host)", traces[1].FormattedMessage);
4254
}
4355

4456
[Fact]

‎test/WebJobs.Script.Tests/WorkerFunctionMetadataProviderTests.cs‎

Lines changed: 35 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3,13 +3,17 @@
33

44
using System;
55
using System.Collections.Generic;
6+
using System.Collections.Immutable;
67
using System.IO;
78
using System.Linq;
9+
using System.Threading.Tasks;
810
using Microsoft.Azure.WebJobs.Script.Description;
911
using Microsoft.Azure.WebJobs.Script.Grpc.Messages;
1012
using Microsoft.Azure.WebJobs.Script.Workers;
13+
using Microsoft.Azure.WebJobs.Script.Workers.Rpc;
1114
using Microsoft.Extensions.Logging;
1215
using Moq;
16+
using NuGet.ContentModel;
1317
using Xunit;
1418

1519
namespace Microsoft.Azure.WebJobs.Script.Tests
@@ -140,5 +144,36 @@ public void ValidateBindings_OutputNameWithoutDirection_Throws()
140144

141145
Assert.Equal($"{ScriptConstants.SystemReturnParameterBindingName} bindings must specify a direction of 'out'.", ex.Message);
142146
}
147+
148+
[Fact]
149+
public async void ValidateFunctionMetadata_Logging()
150+
{
151+
var logger = new TestLogger<WorkerFunctionMetadataProvider>();
152+
logger.ClearLogMessages();
153+
154+
var workerConfigs = TestHelpers.GetTestWorkerConfigs().ToImmutableArray();
155+
workerConfigs.ToList().ForEach(config => config.Description.WorkerIndexing = "true");
156+
157+
var scriptApplicationHostOptions = new ScriptApplicationHostOptions();
158+
var optionsMonitor = TestHelpers.CreateOptionsMonitor(scriptApplicationHostOptions);
159+
160+
var mockWebHostRpcWorkerChannelManager = new Mock<IWebHostRpcWorkerChannelManager>();
161+
mockWebHostRpcWorkerChannelManager.Setup(m => m.GetChannels(It.IsAny<string>())).Returns(() => new Dictionary<string, TaskCompletionSource<IRpcWorkerChannel>>
162+
{
163+
});
164+
165+
var environment = SystemEnvironment.Instance;
166+
environment.SetEnvironmentVariable(EnvironmentSettingNames.FunctionWorkerRuntime, "node");
167+
168+
var workerFunctionMetadataProvider = new WorkerFunctionMetadataProvider(optionsMonitor, logger, SystemEnvironment.Instance, mockWebHostRpcWorkerChannelManager.Object);
169+
await workerFunctionMetadataProvider.GetFunctionMetadataAsync(workerConfigs, false);
170+
171+
var traces = logger.GetLogMessages();
172+
173+
// Assert that the logs contain the expected messages
174+
Assert.Equal(2, traces.Count);
175+
Assert.Equal("Reading functions metadata (Worker)", traces[1].FormattedMessage);
176+
Assert.Equal("Fetching metadata for workerRuntime: node", traces[0].FormattedMessage);
177+
}
143178
}
144179
}

0 commit comments

Comments
 (0)