Skip to content

Commit 76f8595

Browse files
brettsambrettsam
committed
fixing LanguageWorker console.log()
1 parent 7c4e159 commit 76f8595

17 files changed

+205
-63
lines changed

‎src/WebJobs.Script/Rpc/ILanguageWorkerConsoleLogSource.cs‎

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,14 @@
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.Threading.Tasks.Dataflow;
5+
6+
namespace Microsoft.Azure.WebJobs.Script.Rpc
7+
{
8+
public interface ILanguageWorkerConsoleLogSource
9+
{
10+
ISourceBlock<string> LogStream { get; }
11+
12+
void Log(string consoleLog);
13+
}
14+
}

‎src/WebJobs.Script/Rpc/LanguageWorkerChannel.cs‎

Lines changed: 8 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -17,7 +17,6 @@
1717
using Microsoft.Azure.WebJobs.Script.Eventing.Rpc;
1818
using Microsoft.Azure.WebJobs.Script.Grpc.Messages;
1919
using Microsoft.Extensions.Logging;
20-
using Newtonsoft.Json;
2120

2221
using FunctionMetadata = Microsoft.Azure.WebJobs.Script.Description.FunctionMetadata;
2322
using MsgType = Microsoft.Azure.WebJobs.Script.Grpc.Messages.StreamingMessage.ContentOneofCase;
@@ -34,7 +33,7 @@ internal class LanguageWorkerChannel : ILanguageWorkerChannel
3433
private readonly IProcessRegistry _processRegistry;
3534
private readonly WorkerConfig _workerConfig;
3635
private readonly ILogger _workerChannelLogger;
37-
private readonly ILogger _userLogsConsoleLogger;
36+
private readonly ILanguageWorkerConsoleLogSource _consoleLogSource;
3837

3938
private bool _disposed;
4039
private IObservable<FunctionRegistrationContext> _functionRegistrations;
@@ -68,7 +67,8 @@ internal LanguageWorkerChannel(
6867
Uri serverUri,
6968
ILoggerFactory loggerFactory,
7069
IMetricsLogger metricsLogger,
71-
int attemptCount)
70+
int attemptCount,
71+
ILanguageWorkerConsoleLogSource consoleLogSource)
7272
{
7373
_workerId = workerId;
7474
_functionRegistrations = functionRegistrations;
@@ -79,7 +79,7 @@ internal LanguageWorkerChannel(
7979
_workerConfig = workerConfig;
8080
_serverUri = serverUri;
8181
_workerChannelLogger = loggerFactory.CreateLogger($"Worker.{workerConfig.Language}.{_workerId}");
82-
_userLogsConsoleLogger = loggerFactory.CreateLogger(LanguageWorkerConstants.FunctionConsoleLogCategoryName);
82+
_consoleLogSource = consoleLogSource;
8383

8484
_inboundWorkerEvents = _eventManager.OfType<InboundEvent>()
8585
.Where(msg => msg.WorkerId == _workerId);
@@ -138,7 +138,7 @@ private void OnOutputDataReceived(object sender, DataReceivedEventArgs e)
138138
}
139139
else
140140
{
141-
_userLogsConsoleLogger?.LogInformation(msg);
141+
_consoleLogSource?.Log(msg);
142142
}
143143
}
144144
}
@@ -181,7 +181,7 @@ private void OnErrorDataReceived(object sender, DataReceivedEventArgs e)
181181
}
182182
else
183183
{
184-
_userLogsConsoleLogger?.LogInformation(msg);
184+
_consoleLogSource?.Log(msg);
185185
}
186186
}
187187
else if ((msg.IndexOf("error", StringComparison.OrdinalIgnoreCase) > -1) ||
@@ -195,7 +195,7 @@ private void OnErrorDataReceived(object sender, DataReceivedEventArgs e)
195195
}
196196
else
197197
{
198-
_userLogsConsoleLogger?.LogInformation(msg);
198+
_consoleLogSource?.Log(msg);
199199
}
200200
_processStdErrDataQueue = LanguageWorkerChannelUtilities.AddStdErrMessage(_processStdErrDataQueue, Sanitizer.Sanitize(msg));
201201
}
@@ -208,7 +208,7 @@ private void OnErrorDataReceived(object sender, DataReceivedEventArgs e)
208208
}
209209
else
210210
{
211-
_userLogsConsoleLogger?.LogInformation(msg);
211+
_consoleLogSource?.Log(msg);
212212
}
213213
}
214214
}

‎src/WebJobs.Script/Rpc/LanguageWorkerChannelManager.cs‎

Lines changed: 7 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,7 @@ public class LanguageWorkerChannelManager : ILanguageWorkerChannelManager
2424
private readonly TimeSpan processStartTimeout = TimeSpan.FromSeconds(40);
2525
private readonly TimeSpan workerInitTimeout = TimeSpan.FromSeconds(30);
2626
private readonly IOptionsMonitor<ScriptApplicationHostOptions> _applicationHostOptions = null;
27+
private readonly ILanguageWorkerConsoleLogSource _consoleLogSource;
2728
private readonly IScriptEventManager _eventManager = null;
2829
private readonly IEnvironment _environment;
2930
private readonly ILoggerFactory _loggerFactory = null;
@@ -35,7 +36,8 @@ public class LanguageWorkerChannelManager : ILanguageWorkerChannelManager
3536
private Action _shutdownStandbyWorkerChannels;
3637
private IDictionary<string, ILanguageWorkerChannel> _workerChannels = new Dictionary<string, ILanguageWorkerChannel>();
3738

38-
public LanguageWorkerChannelManager(IScriptEventManager eventManager, IEnvironment environment, IRpcServer rpcServer, ILoggerFactory loggerFactory, IOptions<LanguageWorkerOptions> languageWorkerOptions, IOptionsMonitor<ScriptApplicationHostOptions> applicationHostOptions)
39+
public LanguageWorkerChannelManager(IScriptEventManager eventManager, IEnvironment environment, IRpcServer rpcServer, ILoggerFactory loggerFactory, IOptions<LanguageWorkerOptions> languageWorkerOptions,
40+
IOptionsMonitor<ScriptApplicationHostOptions> applicationHostOptions, ILanguageWorkerConsoleLogSource consoleLogSource)
3941
{
4042
_rpcServer = rpcServer;
4143
_environment = environment ?? throw new ArgumentNullException(nameof(environment));
@@ -44,6 +46,8 @@ public LanguageWorkerChannelManager(IScriptEventManager eventManager, IEnvironme
4446
_logger = loggerFactory.CreateLogger(ScriptConstants.LanguageWorkerChannelManager);
4547
_workerConfigs = languageWorkerOptions.Value.WorkerConfigs;
4648
_applicationHostOptions = applicationHostOptions;
49+
_consoleLogSource = consoleLogSource;
50+
4751
_processFactory = new DefaultWorkerProcessFactory();
4852
try
4953
{
@@ -78,7 +82,8 @@ public ILanguageWorkerChannel CreateLanguageWorkerChannel(string workerId, strin
7882
_rpcServer.Uri,
7983
_loggerFactory,
8084
metricsLogger,
81-
attemptCount);
85+
attemptCount,
86+
_consoleLogSource);
8287
}
8388

8489
public async Task InitializeChannelAsync(string runtime)

‎src/WebJobs.Script/Rpc/LanguageWorkerConsoleLogService.cs‎

Lines changed: 69 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,69 @@
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.Threading;
6+
using System.Threading.Tasks;
7+
using System.Threading.Tasks.Dataflow;
8+
using Microsoft.Extensions.Hosting;
9+
using Microsoft.Extensions.Logging;
10+
11+
namespace Microsoft.Azure.WebJobs.Script.Rpc
12+
{
13+
internal class LanguageWorkerConsoleLogService : IHostedService, IDisposable
14+
{
15+
private readonly ILogger _logger;
16+
private readonly ILanguageWorkerConsoleLogSource _source;
17+
private readonly CancellationTokenSource _cts = new CancellationTokenSource();
18+
private Task _processingTask;
19+
private bool _disposed = false;
20+
21+
public LanguageWorkerConsoleLogService(ILoggerFactory loggerFactory, ILanguageWorkerConsoleLogSource consoleLogSource)
22+
{
23+
if (loggerFactory == null)
24+
{
25+
throw new ArgumentNullException(nameof(loggerFactory));
26+
}
27+
28+
_source = consoleLogSource ?? throw new ArgumentNullException(nameof(consoleLogSource));
29+
_logger = loggerFactory.CreateLogger(LanguageWorkerConstants.FunctionConsoleLogCategoryName);
30+
}
31+
32+
public Task StartAsync(CancellationToken cancellationToken)
33+
{
34+
_processingTask = ProcessLogs();
35+
return Task.CompletedTask;
36+
}
37+
38+
public async Task StopAsync(CancellationToken cancellationToken)
39+
{
40+
_cts.Cancel();
41+
await _processingTask;
42+
}
43+
44+
private async Task ProcessLogs()
45+
{
46+
ISourceBlock<string> source = _source.LogStream;
47+
try
48+
{
49+
while (await source.OutputAvailableAsync(_cts.Token))
50+
{
51+
_logger.LogInformation(await source.ReceiveAsync());
52+
}
53+
}
54+
catch (OperationCanceledException)
55+
{
56+
// This occurs during shutdown.
57+
}
58+
}
59+
60+
public void Dispose()
61+
{
62+
if (!_disposed)
63+
{
64+
_cts?.Dispose();
65+
_disposed = true;
66+
}
67+
}
68+
}
69+
}

‎src/WebJobs.Script/Rpc/LanguageWorkerConsoleLogSource.cs‎

Lines changed: 19 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,19 @@
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.Threading.Tasks.Dataflow;
5+
6+
namespace Microsoft.Azure.WebJobs.Script.Rpc
7+
{
8+
internal class LanguageWorkerConsoleLogSource : ILanguageWorkerConsoleLogSource
9+
{
10+
private readonly BufferBlock<string> _buffer = new BufferBlock<string>();
11+
12+
public ISourceBlock<string> LogStream => _buffer;
13+
14+
public void Log(string consoleLog)
15+
{
16+
_buffer.Post(consoleLog);
17+
}
18+
}
19+
}

‎src/WebJobs.Script/ScriptHostBuilderExtensions.cs‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -161,6 +161,7 @@ public static IHostBuilder AddScriptHostCore(this IHostBuilder builder, ScriptAp
161161
}
162162

163163
// Hosted services
164+
services.AddSingleton<IHostedService, LanguageWorkerConsoleLogService>();
164165
services.TryAddEnumerable(ServiceDescriptor.Singleton<IHostedService, PrimaryHostCoordinator>());
165166
});
166167

@@ -182,6 +183,7 @@ public static void AddCommonServices(IServiceCollection services)
182183
services.AddSingleton<IHostedService, RpcInitializationService>();
183184
services.AddSingleton<FunctionRpc.FunctionRpcBase, FunctionRpcService>();
184185
services.AddSingleton<IRpcServer, GrpcServer>();
186+
services.TryAddSingleton<ILanguageWorkerConsoleLogSource, LanguageWorkerConsoleLogSource>();
185187
services.TryAddSingleton<ILanguageWorkerChannelManager, LanguageWorkerChannelManager>();
186188

187189
services.TryAddSingleton<IDebugManager, DebugManager>();

‎test/WebJobs.Script.Tests.Integration/CosmosDB/CosmosDBEndToEndTestsBase.cs‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -45,7 +45,7 @@ protected async Task CosmosDBTriggerToBlobTest()
4545

4646
// now wait for function to be invoked
4747
string result = await TestHelpers.WaitForBlobAndGetStringAsync(resultBlob,
48-
() => string.Join(Environment.NewLine, Fixture.Host.GetLogMessages()));
48+
() => string.Join(Environment.NewLine, Fixture.Host.GetScriptHostLogMessages()));
4949

5050
if (collectionsCreated)
5151
{

‎test/WebJobs.Script.Tests.Integration/Host/WebJobsScriptHostServiceTests.cs‎

Lines changed: 22 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -63,7 +63,7 @@ public WebJobsScriptHostServiceTests()
6363
foreach (var counter in _exceededCounters)
6464
{
6565
c.Add(counter);
66-
}
66+
}
6767
}
6868
})
6969
.Returns(() => _underHighLoad);
@@ -90,19 +90,29 @@ public WebJobsScriptHostServiceTests()
9090
public void InitializationLogs_AreEmitted()
9191
{
9292
// verify startup trace logs
93-
string[] expectedPatterns = new string[]
93+
string[] expectedPatternsWebHost = new string[]
9494
{
9595
"Information Reading host configuration file",
9696
"Information Host configuration file read",
97+
};
98+
99+
string[] expectedPatternsScriptHost = new string[]
100+
{
97101
@"Information Generating 2 job function\(s\)",
98102
"Host initialization: ConsecutiveErrors=0, StartupCount=1",
99103
@"Information Starting Host \(HostId=(.*), InstanceId=(.*), Version=(.+), ProcessId=[0-9]+, AppDomainId=[0-9]+, InDebugMode=False, InDiagnosticMode=False, FunctionsExtensionVersion=\)",
100104
"Information Found the following functions:",
101105
"Information Job host started",
102106
};
103107

104-
IList<LogMessage> logs = _testHost.GetLogMessages();
105-
foreach (string pattern in expectedPatterns)
108+
IList<LogMessage> logs = _testHost.GetWebHostLogMessages();
109+
foreach (string pattern in expectedPatternsWebHost)
110+
{
111+
Assert.True(logs.Any(p => Regex.IsMatch($"{p.Level} {p.FormattedMessage}", pattern)), $"Expected trace event {pattern} not found.");
112+
}
113+
114+
logs = _testHost.GetScriptHostLogMessages();
115+
foreach (string pattern in expectedPatternsScriptHost)
106116
{
107117
Assert.True(logs.Any(p => Regex.IsMatch($"{p.Level} {p.FormattedMessage}", pattern)), $"Expected trace event {pattern} not found.");
108118
}
@@ -130,18 +140,20 @@ public async Task HostHealthMonitor_TriggersShutdown_WhenHostUnhealthy()
130140
_mockJobHostEnvironment.Verify(p => p.Shutdown(), Times.Once);
131141

132142
// we expect a few restart iterations
133-
var logMessages = _testHost.GetLogMessages();
134-
var thresholdErrors = logMessages.Where(p => p.Exception is InvalidOperationException && p.Exception.Message == "Host thresholds exceeded: [Connections]. For more information, see https://aka.ms/functions-thresholds.");
143+
var scriptHostLogMessages = _testHost.GetScriptHostLogMessages();
144+
var webHostLogMessages = _testHost.GetWebHostLogMessages();
145+
146+
var thresholdErrors = scriptHostLogMessages.Where(p => p.Exception is InvalidOperationException && p.Exception.Message == "Host thresholds exceeded: [Connections]. For more information, see https://aka.ms/functions-thresholds.");
135147
var count = thresholdErrors.Count();
136148
Assert.True(count > 0);
137149

138-
var log = logMessages.First(p => p.FormattedMessage == "Host is unhealthy. Initiating a restart." && p.Level == LogLevel.Error);
150+
var log = webHostLogMessages.First(p => p.FormattedMessage == "Host is unhealthy. Initiating a restart." && p.Level == LogLevel.Error);
139151
Assert.Equal(LogLevel.Error, log.Level);
140152

141-
log = logMessages.First(p => p.FormattedMessage == "Host unhealthy count exceeds the threshold of 5 for time window 00:00:01. Initiating shutdown.");
153+
log = webHostLogMessages.First(p => p.FormattedMessage == "Host unhealthy count exceeds the threshold of 5 for time window 00:00:01. Initiating shutdown.");
142154
Assert.Equal(LogLevel.Error, log.Level);
143155

144-
Assert.Contains(logMessages, p => p.FormattedMessage == "Stopping JobHost");
156+
Assert.Contains(scriptHostLogMessages, p => p.FormattedMessage == "Stopping JobHost");
145157
}
146158

147159
[Fact]
@@ -179,7 +191,7 @@ await TestHelpers.Await(() =>
179191
await TestHelpers.Await(() => _scriptHostService.State == ScriptHostState.Running);
180192
Assert.Null(_scriptHostService.LastError);
181193

182-
var logMessages = _testHost.GetLogMessages();
194+
var logMessages = _testHost.GetScriptHostLogMessages();
183195
Assert.Contains(logMessages, p => p.FormattedMessage == "Job host started");
184196
}
185197

‎test/WebJobs.Script.Tests.Integration/TestFunctionHost.cs‎

Lines changed: 19 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -32,7 +32,8 @@ public class TestFunctionHost : IDisposable
3232
private readonly ScriptApplicationHostOptions _hostOptions;
3333
private readonly TestServer _testServer;
3434
private readonly string _appRoot;
35-
private readonly TestLoggerProvider _loggerProvider = new TestLoggerProvider();
35+
private readonly TestLoggerProvider _webHostLoggerProvider = new TestLoggerProvider();
36+
private readonly TestLoggerProvider _scriptHostLoggerProvider = new TestLoggerProvider();
3637
private readonly WebJobsScriptHostService _hostService;
3738

3839
public TestFunctionHost(string scriptPath, string logPath,
@@ -55,7 +56,7 @@ public TestFunctionHost(string scriptPath, string logPath,
5556
var builder = new WebHostBuilder()
5657
.ConfigureLogging(b =>
5758
{
58-
b.AddProvider(_loggerProvider);
59+
b.AddProvider(_webHostLoggerProvider);
5960
})
6061
.ConfigureServices(services =>
6162
{
@@ -76,7 +77,7 @@ public TestFunctionHost(string scriptPath, string logPath,
7677
{
7778
webJobsBuilder.Services.AddLogging(loggingBuilder =>
7879
{
79-
loggingBuilder.AddProvider(_loggerProvider);
80+
loggingBuilder.AddProvider(_scriptHostLoggerProvider);
8081
loggingBuilder.AddFilter<TestLoggerProvider>(_ => true);
8182
});
8283

@@ -161,13 +162,24 @@ public static void WriteNugetPackageSources(string appRoot, params string[] sour
161162
}
162163
}
163164

164-
public IList<LogMessage> GetLogMessages() => _loggerProvider.GetAllLogMessages();
165+
/// <summary>
166+
/// The functions host has two logger providers -- one at the WebHost level and one at the ScriptHost level.
167+
/// These providers use different LoggerProviders, so it's important to know which one is receiving the logs.
168+
/// </summary>
169+
/// <returns>The messages from the ScriptHost LoggerProvider</returns>
170+
public IList<LogMessage> GetScriptHostLogMessages() => _scriptHostLoggerProvider.GetAllLogMessages();
171+
public IEnumerable<LogMessage> GetScriptHostLogMessages(string category) => GetScriptHostLogMessages().Where(p => p.Category == category);
165172

166-
public IEnumerable<LogMessage> GetLogMessages(string category) => GetLogMessages().Where(p => p.Category == category);
173+
/// <summary>
174+
/// The functions host has two logger providers -- one at the WebHost level and one at the ScriptHost level.
175+
/// These providers use different LoggerProviders, so it's important to know which one is receiving the logs.
176+
/// </summary>
177+
/// <returns>The messages from the WebHost LoggerProvider</returns>
178+
public IList<LogMessage> GetWebHostLogMessages() => _webHostLoggerProvider.GetAllLogMessages();
167179

168-
public string GetLog() => string.Join(Environment.NewLine, GetLogMessages());
180+
public string GetLog() => string.Join(Environment.NewLine, GetScriptHostLogMessages());
169181

170-
public void ClearLogMessages() => _loggerProvider.ClearAllLogMessages();
182+
public void ClearLogMessages() => _scriptHostLoggerProvider.ClearAllLogMessages();
171183

172184
public async Task BeginFunctionAsync(string functionName, JToken payload)
173185
{

‎test/WebJobs.Script.Tests.Integration/TestScripts/Node/Scenarios/index.js‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -41,6 +41,8 @@ module.exports = function (context, input) {
4141
context.log.warn('loglevel warn');
4242
context.log.error('loglevel error');
4343

44+
console.log('console log');
45+
4446
context.done();
4547
}
4648
else if (scenario === 'bindingData') {

0 commit comments

Comments
 (0)