Skip to content

Commit 0766b39

Browse files
mathewcmathewc
committed
Fixing coldstart logging issues (#2186)
1 parent 7f7e420 commit 0766b39

File tree

3 files changed

+79
-29
lines changed

3 files changed

+79
-29
lines changed

‎src/WebJobs.Script.WebHost/App_Start/WebHostResolver.cs‎

Lines changed: 50 additions & 24 deletions
Original file line numberDiff line numberDiff line change
@@ -20,7 +20,6 @@ namespace Microsoft.Azure.WebJobs.Script.WebHost
2020
public sealed class WebHostResolver : IDisposable
2121
{
2222
private static ScriptSettingsManager _settingsManager;
23-
private static ILoggerFactory _emptyLoggerFactory = new LoggerFactory();
2423
private static object _syncLock = new object();
2524

2625
private readonly ISecretManagerFactory _secretManagerFactory;
@@ -31,6 +30,7 @@ public sealed class WebHostResolver : IDisposable
3130
private ScriptHostConfiguration _activeScriptHostConfig;
3231
private WebScriptHostManager _activeHostManager;
3332
private WebHookReceiverManager _activeReceiverManager;
33+
private ILoggerFactory _defaultLoggerFactory;
3434
private TraceWriter _defaultTraceWriter;
3535
private Timer _specializationTimer;
3636

@@ -43,45 +43,57 @@ public WebHostResolver(ScriptSettingsManager settingsManager, ISecretManagerFact
4343

4444
public ILoggerFactory GetLoggerFactory(WebHostSettings settings)
4545
{
46-
WebScriptHostManager manager = GetWebScriptHostManager(settings);
47-
48-
if (!manager.CanInvoke())
46+
// if we have an active initialized host, return it's fully configured
47+
// logger factory
48+
var hostManager = GetWebScriptHostManager(settings);
49+
if (hostManager.CanInvoke())
4950
{
50-
// The host is still starting and the LoggerFactory cannot be used. Return
51-
// an empty LoggerFactory rather than waiting. This will mostly affect
52-
// calls to /admin/host/status, which do not block on CanInvoke. It allows this
53-
// API to remain fast with the side effect of occassional missed logs.
54-
return _emptyLoggerFactory;
51+
var config = GetScriptHostConfiguration(settings);
52+
return config.HostConfig.LoggerFactory;
53+
}
54+
else
55+
{
56+
// if there is no active host, return the default logger factory
57+
if (_defaultLoggerFactory == null)
58+
{
59+
lock (_syncLock)
60+
{
61+
if (_defaultLoggerFactory == null)
62+
{
63+
_defaultLoggerFactory = CreateDefaultLoggerFactory(settings);
64+
}
65+
}
66+
}
67+
68+
return _defaultLoggerFactory;
5569
}
56-
57-
return GetScriptHostConfiguration(settings).HostConfig.LoggerFactory;
5870
}
5971

6072
public TraceWriter GetTraceWriter(WebHostSettings settings)
6173
{
62-
// if we have an active host, return it's fully configured
74+
// if we have an active initialized host, return it's fully configured
6375
// trace writer
6476
var hostManager = GetWebScriptHostManager(settings);
65-
var traceWriter = hostManager.Instance?.TraceWriter;
66-
67-
if (traceWriter != null)
77+
if (hostManager.CanInvoke())
6878
{
69-
return traceWriter;
79+
return hostManager.Instance.TraceWriter;
7080
}
71-
72-
// if there is no active host, return the default trace writer
73-
if (_defaultTraceWriter == null)
81+
else
7482
{
75-
lock (_syncLock)
83+
// if there is no active host, return the default trace writer
84+
if (_defaultTraceWriter == null)
7685
{
77-
if (_defaultTraceWriter == null)
86+
lock (_syncLock)
7887
{
79-
_defaultTraceWriter = CreateDefaultTraceWriter(settings);
88+
if (_defaultTraceWriter == null)
89+
{
90+
_defaultTraceWriter = CreateDefaultTraceWriter(settings);
91+
}
8092
}
8193
}
82-
}
8394

84-
return _defaultTraceWriter;
95+
return _defaultTraceWriter;
96+
}
8597
}
8698

8799
public ISwaggerDocumentManager GetSwaggerDocumentManager(WebHostSettings settings)
@@ -239,6 +251,19 @@ private TraceWriter CreateDefaultTraceWriter(WebHostSettings settings)
239251
return new CompositeTraceWriter(new[] { systemTraceWriter, fileTraceWriter });
240252
}
241253

254+
private ILoggerFactory CreateDefaultLoggerFactory(WebHostSettings settings)
255+
{
256+
var loggerFactory = new LoggerFactory();
257+
if (!string.IsNullOrEmpty(_settingsManager.ApplicationInsightsInstrumentationKey))
258+
{
259+
var config = GetScriptHostConfiguration(settings);
260+
var clientFactory = new ScriptTelemetryClientFactory(_settingsManager.ApplicationInsightsInstrumentationKey, config.ApplicationInsightsSamplingSettings, config.LogFilter.Filter);
261+
loggerFactory.AddApplicationInsights(clientFactory);
262+
}
263+
264+
return loggerFactory;
265+
}
266+
242267
/// <summary>
243268
/// Helper function used to manage active/standby transitions for objects managed
244269
/// by this class.
@@ -339,6 +364,7 @@ public void Dispose()
339364
_activeHostManager?.Dispose();
340365
_activeReceiverManager?.Dispose();
341366
((IDisposable)_defaultTraceWriter)?.Dispose();
367+
_defaultLoggerFactory?.Dispose();
342368
}
343369
}
344370
}

‎src/WebJobs.Script.WebHost/GlobalSuppressions.cs‎

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -110,4 +110,7 @@
110110
[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Usage", "CA1801:ReviewUnusedParameters", MessageId = "host", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.WebHost.StandbyManager.#WarmUp(Microsoft.Azure.WebJobs.Script.ScriptHost)")]
111111
[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Usage", "CA1801:ReviewUnusedParameters", MessageId = "settings", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.WebHost.WebHostResolver.#GetPerformanceManager(Microsoft.Azure.WebJobs.Script.WebHost.WebHostSettings)")]
112112
[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Usage", "CA2213:DisposableFieldsShouldBeDisposed", MessageId = "_specializationTimer", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.WebHost.WebHostResolver.#Dispose()")]
113-
[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.WebHost.WebHostResolver.#CreateDefaultTraceWriter(Microsoft.Azure.WebJobs.Script.WebHost.WebHostSettings)")]
113+
[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.WebHost.WebHostResolver.#CreateDefaultTraceWriter(Microsoft.Azure.WebJobs.Script.WebHost.WebHostSettings)")]
114+
[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Usage", "CA2213:DisposableFieldsShouldBeDisposed", MessageId = "_defaultLoggerFactory", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.WebHost.WebHostResolver.#Dispose()")]
115+
[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.WebHost.WebHostResolver.#CreateDefaultLoggerFactory(Microsoft.Azure.WebJobs.Script.WebHost.WebHostSettings)")]
116+

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

Lines changed: 25 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,7 @@
1212
using Microsoft.Azure.WebJobs.Script.Eventing;
1313
using Microsoft.Azure.WebJobs.Script.WebHost;
1414
using Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics;
15+
using Microsoft.Extensions.Logging;
1516
using Moq;
1617
using Xunit;
1718

@@ -65,7 +66,7 @@ public void CreateScriptHostConfiguration_StandbyMode_ReturnsExpectedConfigurati
6566
}
6667

6768
[Fact]
68-
public async Task GetTraceWriter_ReturnsExpectedValue()
69+
public async Task GetTraceWriter_GetLogger_ReturnsExpectedValue()
6970
{
7071
var settingsManager = new ScriptSettingsManager();
7172
var secretManagerFactoryMock = new Mock<ISecretManagerFactory>();
@@ -81,6 +82,11 @@ public async Task GetTraceWriter_ReturnsExpectedValue()
8182
ScriptPath = Path.Combine(tempRoot, @"Functions"),
8283
SecretsPath = Path.Combine(tempRoot, @"Functions"),
8384
};
85+
File.WriteAllText(Path.Combine(settings.ScriptPath, "host.json"), "{ id: 'testid' }");
86+
87+
var secretsManagerMock = new Mock<ISecretManager>();
88+
secretsManagerMock.Setup(p => p.PurgeOldSecretsAsync(settings.SecretsPath, It.IsAny<TraceWriter>(), It.IsAny<ILogger>())).Returns(Task.CompletedTask);
89+
secretManagerFactoryMock.Setup(p => p.Create(settingsManager, It.IsAny<TraceWriter>(), It.IsAny<ILoggerFactory>(), It.IsAny<ISecretsRepository>())).Returns(secretsManagerMock.Object);
8490

8591
// ensure that the returned trace writer isn't null even though the
8692
// host hasn't been initialized yet
@@ -104,13 +110,28 @@ public async Task GetTraceWriter_ReturnsExpectedValue()
104110
var logs = await TestHelpers.GetHostLogsAsync();
105111
Assert.True(logs.Single().Contains(id));
106112

107-
// now wait for the host to be initialized and verify the trace
108-
// writer returned is the host trace writer
113+
// ensure that the returned logger factory isn't null even though the host
114+
// hasn't been initialized yet
115+
var loggerFactory = resolver.GetLoggerFactory(settings);
116+
Assert.NotNull(loggerFactory);
117+
118+
// now wait for the host to be fully initialized
109119
Task ignored = Task.Run(() => hostManager.RunAndBlock());
110-
await TestHelpers.Await(() => hostManager.Instance != null);
120+
await TestHelpers.Await(() => hostManager.State == ScriptHostState.Error || hostManager.CanInvoke());
111121

122+
if (hostManager.State == ScriptHostState.Error)
123+
{
124+
Assert.True(false, hostManager.LastError.Message);
125+
}
126+
127+
// verify the trace writer returned is the host trace writer
112128
traceWriter = resolver.GetTraceWriter(settings);
113129
Assert.Same(hostManager.Instance.TraceWriter, traceWriter);
130+
131+
// verify the logger factory returned is the host trace writer
132+
var config = resolver.GetScriptHostConfiguration(settings);
133+
loggerFactory = resolver.GetLoggerFactory(settings);
134+
Assert.Same(loggerFactory, config.HostConfig.LoggerFactory);
114135
}
115136
}
116137
}

0 commit comments

Comments
 (0)