Skip to content

Commit f3eca20

Browse files
fabiocavfabiocav
authored
Implementing diagnostic listener service (#8524)
* Implementing diagnostic listener service * PR feedback
1 parent a884224 commit f3eca20

File tree

5 files changed

+313
-0
lines changed

5 files changed

+313
-0
lines changed

‎src/WebJobs.Script.WebHost/Diagnostics/DiagnosticListenerService.cs‎

Lines changed: 136 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,136 @@
1+
// Copyright (c) .NET Foundation. All rights reserved.
2+
// Licensed under the MIT License. See License.txt in the project root for license information.
3+
4+
using System;
5+
using System.Collections.Generic;
6+
using System.Diagnostics;
7+
using System.Threading;
8+
using System.Threading.Tasks;
9+
using Microsoft.Azure.WebJobs.Script.Config;
10+
using Microsoft.Azure.WebJobs.Script.Diagnostics;
11+
using Microsoft.Extensions.Hosting;
12+
using Microsoft.Extensions.Logging;
13+
using Microsoft.Extensions.Options;
14+
15+
namespace Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics
16+
{
17+
public sealed class DiagnosticListenerService : IHostedService, IDisposable
18+
{
19+
private readonly ILogger<DiagnosticListenerService> _logger;
20+
private readonly Dictionary<string, IDisposable> _listenerSubscriptions;
21+
private readonly IDisposable _standbyChangeHandler;
22+
private static bool _debugTraceEnabled;
23+
private IDisposable _allListenersSubscription;
24+
private bool _disposed;
25+
26+
public DiagnosticListenerService(ILogger<DiagnosticListenerService> logger, IOptionsMonitor<StandbyOptions> standbyOptions)
27+
{
28+
_logger = logger;
29+
_listenerSubscriptions = new Dictionary<string, IDisposable>();
30+
31+
SetDebugState();
32+
33+
if (standbyOptions.CurrentValue.InStandbyMode)
34+
{
35+
_standbyChangeHandler = standbyOptions.OnChange(o => SetDebugState());
36+
}
37+
}
38+
39+
private static void SetDebugState() => _debugTraceEnabled = FeatureFlags.IsEnabled(ScriptConstants.FeatureFlagEnableDebugTracing);
40+
41+
private void SubscribeListeners()
42+
{
43+
if (_allListenersSubscription != null)
44+
{
45+
_allListenersSubscription.Dispose();
46+
}
47+
48+
_allListenersSubscription = DiagnosticListener.AllListeners.Subscribe(delegate (DiagnosticListener listener)
49+
{
50+
if (listener.Name.StartsWith(ScriptConstants.HostDiagnosticSourcePrefix))
51+
{
52+
lock (_listenerSubscriptions)
53+
{
54+
IDisposable listenerSubscription = listener.Subscribe(new HostListenerObserver(listener.Name, _logger), IsEventEnabled);
55+
56+
if (!_listenerSubscriptions.TryAdd(listener.Name, listenerSubscription))
57+
{
58+
if (_listenerSubscriptions.Remove(listener.Name, out IDisposable existingSubscription))
59+
{
60+
existingSubscription.Dispose();
61+
}
62+
63+
_listenerSubscriptions.Add(listener.Name, listenerSubscription);
64+
}
65+
66+
_logger.LogInformation("Subscribed to host diagnostic source '{sourceName}'", listener.Name);
67+
}
68+
}
69+
});
70+
}
71+
72+
private bool IsEventEnabled(string eventName)
73+
{
74+
return !eventName.StartsWith(ScriptConstants.HostDiagnosticSourceDebugEventNamePrefix) || _debugTraceEnabled;
75+
}
76+
77+
public Task StartAsync(CancellationToken cancellationToken)
78+
{
79+
SubscribeListeners();
80+
81+
return Task.CompletedTask;
82+
}
83+
84+
public Task StopAsync(CancellationToken cancellationToken)
85+
{
86+
return Task.CompletedTask;
87+
}
88+
89+
public void Dispose()
90+
{
91+
if (_disposed)
92+
{
93+
return;
94+
}
95+
96+
_allListenersSubscription?.Dispose();
97+
_standbyChangeHandler?.Dispose();
98+
99+
foreach (var item in _listenerSubscriptions)
100+
{
101+
item.Value.Dispose();
102+
}
103+
104+
_listenerSubscriptions.Clear();
105+
_disposed = true;
106+
}
107+
108+
private class HostListenerObserver : IObserver<KeyValuePair<string, object>>
109+
{
110+
private readonly string _listenerName;
111+
private readonly ILogger _logger;
112+
113+
public HostListenerObserver(string listenerName, ILogger logger)
114+
{
115+
_listenerName = listenerName;
116+
_logger = logger;
117+
}
118+
119+
public void OnCompleted() { }
120+
121+
public void OnError(Exception error) { }
122+
123+
public void OnNext(KeyValuePair<string, object> kvp)
124+
{
125+
if (kvp.Value is IHostDiagnosticEvent diagnosticEvent)
126+
{
127+
diagnosticEvent.LogEvent(_logger);
128+
}
129+
else
130+
{
131+
_logger.LogDebug("Diagnostic source '{source}' emitted event '{eventName}': {payload}", _listenerName, kvp.Key, kvp.Value);
132+
}
133+
}
134+
}
135+
}
136+
}

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

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -162,6 +162,10 @@ public static void AddWebJobsScriptHost(this IServiceCollection services, IConfi
162162
// Performs function assembly analysis to generete log use of unoptimized assemblies.
163163
services.AddSingleton<IHostedService, AssemblyAnalyzer.AssemblyAnalysisService>();
164164

165+
// Manages a diagnostic listener that subscribes to diagnostic sources setup in the host
166+
// and persists events in the logging infrastructure.
167+
services.AddSingleton<IHostedService, DiagnosticListenerService>();
168+
165169
// Handles shutdown of services that need to happen after StopAsync() of all services of type IHostedService are complete.
166170
// Order is important.
167171
// All other IHostedService injections need to go before this.

‎src/WebJobs.Script/Diagnostics/IHostDiagnosticEvent.cs‎

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,15 @@
1+
// Copyright (c) .NET Foundation. All rights reserved.
2+
// Licensed under the MIT License. See License.txt in the project root for license information.
3+
4+
using System;
5+
using System.Collections.Generic;
6+
using System.Text;
7+
using Microsoft.Extensions.Logging;
8+
9+
namespace Microsoft.Azure.WebJobs.Script.Diagnostics
10+
{
11+
internal interface IHostDiagnosticEvent
12+
{
13+
void LogEvent(ILogger logger);
14+
}
15+
}

‎src/WebJobs.Script/ScriptConstants.cs‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -110,6 +110,7 @@ public static class ScriptConstants
110110
public const string FeatureFlagDisableDiagnosticEventLogging = "DisableDiagnosticEventLogging";
111111
public const string FeatureFlagDisableMergedWebHostScriptHostConfiguration = "DisableMergedConfiguration";
112112
public const string FeatureFlagEnableWorkerIndexing = "EnableWorkerIndexing";
113+
public const string FeatureFlagEnableDebugTracing = "EnableDebugTracing";
113114

114115
public const string AdminJwtValidAudienceFormat = "https://{0}.azurewebsites.net/azurefunctions";
115116
public const string AdminJwtValidIssuerFormat = "https://{0}.scm.azurewebsites.net";
@@ -185,6 +186,11 @@ public static class ScriptConstants
185186
public const string HelpLinkKey = "MS_HelpLink";
186187
public const string ErrorCodeKey = "MS_ErrorCode";
187188

189+
// Diagnostic sources
190+
public const string HostDiagnosticSourcePrefix = "Microsoft.Azure.Functions.Host.";
191+
public const string HostDiagnosticSourceDebugEventNamePrefix = "debug-";
192+
public const string DiagnosticSourceAssemblyContext = HostDiagnosticSourcePrefix + "AssemblyContext";
193+
188194
public static readonly ImmutableArray<string> HttpMethods = ImmutableArray.Create("get", "post", "delete", "head", "patch", "put", "options");
189195
public static readonly ImmutableArray<string> AssemblyFileTypes = ImmutableArray.Create(".dll", ".exe");
190196
public static readonly string HostUserAgent = $"azure-functions-host/{ScriptHost.Version}";

‎test/WebJobs.Script.Tests/Diagnostics/DiagnosticListenerServiceTests.cs‎

Lines changed: 152 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,152 @@
1+
// Copyright (c) .NET Foundation. All rights reserved.
2+
// Licensed under the MIT License. See License.txt in the project root for license information.
3+
4+
using System;
5+
using System.Diagnostics;
6+
using System.Linq;
7+
using System.Threading;
8+
using System.Threading.Tasks;
9+
using Microsoft.Azure.WebJobs.Script.WebHost;
10+
using Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics;
11+
using Microsoft.Extensions.Options;
12+
using Moq;
13+
using Xunit;
14+
using static Microsoft.Azure.WebJobs.Script.ScriptConstants;
15+
16+
namespace Microsoft.Azure.WebJobs.Script.Tests.Diagnostics
17+
{
18+
public class DiagnosticListenerServiceTests
19+
{
20+
/// <summary>
21+
/// This test ensures that:
22+
/// 1 - Diagnostic sources with the host prefix is correctly observed
23+
/// 2 - Diagnostic sources with names not starting with the host prefix
24+
/// are not observed.
25+
/// </summary>
26+
[Fact]
27+
public async Task CreatesExpectedListeners()
28+
{
29+
var logger = new TestLogger<DiagnosticListenerService>();
30+
var om = new Mock<IOptionsMonitor<StandbyOptions>>();
31+
om.Setup(m => m.CurrentValue).Returns(new StandbyOptions());
32+
33+
var service = new DiagnosticListenerService(logger, om.Object);
34+
35+
await service.StartAsync(CancellationToken.None);
36+
37+
// Host diagnostic source
38+
using var source = new DiagnosticListener(HostDiagnosticSourcePrefix + "Test");
39+
source.Write("TestEvent", "test");
40+
41+
// Diagnostic source without hosts prefix
42+
using var source2 = new DiagnosticListener("OtherSource.Test");
43+
source2.Write("TestEvent2", "test");
44+
45+
Assert.Contains(GetEventMessge(source.Name, "TestEvent", "test"), logger.GetLogMessages().Select(l => l.FormattedMessage));
46+
47+
// This assertion accounts for the log message written when a listener handler is created.
48+
Assert.Equal(2, logger.GetLogMessages().Count);
49+
}
50+
51+
/// <summary>
52+
/// This test ensures that enablement evaluation for events starting wiht the debug prefix
53+
/// return false if debug tracing is not enabled.
54+
/// </summary>
55+
[Theory]
56+
[InlineData(true)]
57+
[InlineData(false)]
58+
public async Task CapturesDebugEvents_WhenDebugTracesAreEnabled(bool debugTracingEnabled)
59+
{
60+
TestScopedEnvironmentVariable featureFlags = null;
61+
62+
try
63+
{
64+
if (debugTracingEnabled)
65+
{
66+
featureFlags = new TestScopedEnvironmentVariable(EnvironmentSettingNames.AzureWebJobsFeatureFlags, FeatureFlagEnableDebugTracing);
67+
}
68+
69+
var logger = new TestLogger<DiagnosticListenerService>();
70+
var om = new Mock<IOptionsMonitor<StandbyOptions>>();
71+
om.Setup(m => m.CurrentValue).Returns(new StandbyOptions());
72+
73+
var service = new DiagnosticListenerService(logger, om.Object);
74+
75+
await service.StartAsync(CancellationToken.None);
76+
77+
// Host diagnostic source
78+
using var source = new DiagnosticListener(HostDiagnosticSourcePrefix + "Test");
79+
80+
// Debug event. This will only be captured if debug tracing is enabled:
81+
var eventName = HostDiagnosticSourceDebugEventNamePrefix + "TestEvent";
82+
if (source.IsEnabled(eventName))
83+
{
84+
source.Write(eventName, "test debug");
85+
}
86+
87+
// This event should always be captured
88+
source.Write("TestEvent", "test");
89+
90+
var messages = logger.GetLogMessages().Select(l => l.FormattedMessage).ToList();
91+
92+
Assert.Contains(GetEventMessge(source.Name, "TestEvent", "test"), messages);
93+
94+
if (debugTracingEnabled)
95+
{
96+
Assert.Contains(GetEventMessge(source.Name, eventName, "test debug"), messages);
97+
}
98+
99+
int expectedMessageCount = debugTracingEnabled ? 3 : 2;
100+
// This assertion accounts for the log message written when a listener handler is created.
101+
Assert.Equal(expectedMessageCount, messages.Count);
102+
103+
Assert.Equal(debugTracingEnabled, source.IsEnabled(eventName));
104+
}
105+
finally
106+
{
107+
featureFlags?.Dispose();
108+
}
109+
}
110+
111+
/// <summary>
112+
/// This test ensures that specialization events trigger evaluation of the debug flag and source subscription.
113+
/// </summary>
114+
[Fact]
115+
public async Task StandbyChanges_TriggerFeatureEvaluation()
116+
{
117+
Action<StandbyOptions, string> action = null;
118+
void ChangeCallback(Action<StandbyOptions, string> callback)
119+
{
120+
action = callback;
121+
}
122+
123+
var logger = new TestLogger<DiagnosticListenerService>();
124+
var om = new Mock<IOptionsMonitor<StandbyOptions>>();
125+
om.Setup(m => m.CurrentValue).Returns(new StandbyOptions { InStandbyMode = true });
126+
om.Setup(m => m.OnChange(It.IsAny<Action<StandbyOptions, string>>()))
127+
.Callback(ChangeCallback);
128+
129+
var service = new DiagnosticListenerService(logger, om.Object);
130+
131+
await service.StartAsync(CancellationToken.None);
132+
133+
// Host diagnostic source
134+
using var source = new DiagnosticListener(HostDiagnosticSourcePrefix + "Test");
135+
136+
// Debug event. This will only be captured if debug tracing is enabled:
137+
var eventName = HostDiagnosticSourceDebugEventNamePrefix + "TestEvent";
138+
139+
Assert.False(source.IsEnabled(eventName));
140+
141+
using var featureFlags = new TestScopedEnvironmentVariable(EnvironmentSettingNames.AzureWebJobsFeatureFlags, FeatureFlagEnableDebugTracing);
142+
143+
// Invoke change callback
144+
action(new StandbyOptions(), string.Empty);
145+
146+
Assert.True(source.IsEnabled(eventName));
147+
}
148+
149+
private static string GetEventMessge(string source, string eventName, string payload)
150+
=> $"Diagnostic source '{source}' emitted event '{eventName}': {payload}";
151+
}
152+
}

0 commit comments

Comments
 (0)