diff --git a/SW.Serverless.UnitTests/AdapterStderrTests.cs b/SW.Serverless.UnitTests/AdapterStderrTests.cs new file mode 100644 index 0000000..f459349 --- /dev/null +++ b/SW.Serverless.UnitTests/AdapterStderrTests.cs @@ -0,0 +1,77 @@ +using Microsoft.Extensions.Caching.Memory; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +using Microsoft.VisualStudio.TestTools.UnitTesting; +using SW.PrimitiveTypes; +using System; +using System.Collections.Concurrent; +using System.IO; +using System.Linq; +using System.Threading.Tasks; + +namespace SW.Serverless.UnitTests +{ + /// + /// An adapter dotnet will not start - built for a runtime that is not installed, or packaged + /// without its files. dotnet says why on stderr and exits before the SDK runs, so the line + /// has no marker. The host used to drop it, which left the call failing with "Received null + /// data." and the reason nowhere at all. + /// + [TestClass] + public class AdapterStderrTests + { + [TestMethod] + public async Task What_dotnet_prints_about_an_adapter_it_cannot_start_is_logged() + { + var directory = Directory.CreateTempSubdirectory(); + var adapterPath = Path.Combine(directory.FullName, "broken.adapter.dll"); + await File.WriteAllTextAsync(adapterPath, "not an assembly"); + + var log = new WarningLog(); + using var loggerFactory = LoggerFactory.Create(b => b.AddProvider(log)); + var serverless = new ServerlessService(new ServerlessOptions(), new MemoryCache(new MemoryCacheOptions()), + loggerFactory, new ServiceCollection().BuildServiceProvider()); + + try + { + await serverless.StartAsync("broken.adapter", Guid.NewGuid().ToString("N"), adapterPath); + await Assert.ThrowsExceptionAsync(() => serverless.InvokeAsync("Handle", null)); + } + catch (IOException) + { + // Writing the command can also fail outright, when the process is already gone. + } + finally + { + ((IDisposable)serverless).Dispose(); + } + + // stderr is read on its own thread, so the line can land after the call has failed. + for (var i = 0; i < 50 && log.Lines.IsEmpty; i++) await Task.Delay(100); + + Assert.IsTrue(log.Lines.Any(l => l.Category == "serverless.adapters.broken.adapter"), + "dotnet's reason for not starting the adapter was not logged"); + directory.Delete(true); + } + + sealed class WarningLog : ILoggerProvider + { + public ConcurrentQueue<(string Category, string Message)> Lines { get; } = new(); + + public ILogger CreateLogger(string categoryName) => new Logger(this, categoryName); + public void Dispose() { } + + sealed class Logger(WarningLog log, string category) : ILogger + { + public IDisposable BeginScope(TState state) where TState : notnull => null; + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, + Func formatter) + { + if (logLevel == LogLevel.Warning) log.Lines.Enqueue((category, formatter(state, exception))); + } + } + } + } +} diff --git a/SW.Serverless/Services/ServerlessService.cs b/SW.Serverless/Services/ServerlessService.cs index 4426050..4775eef 100644 --- a/SW.Serverless/Services/ServerlessService.cs +++ b/SW.Serverless/Services/ServerlessService.cs @@ -289,6 +289,13 @@ void ErrorDataReceived(object sender, DataReceivedEventArgs args) { adapterLogger.LogError(args.Data.Replace(Constants.LogErrorIdentifier, "").Replace(Constants.NewLineIdentifier, "\n")); } + // A line without a marker was not written by the SDK: dotnet saying why it would not + // start the adapter, or the runtime reporting a crash. Dropping it left an adapter + // that died with no reason anywhere, only "Received null data." on the call. + else if (!string.IsNullOrWhiteSpace(args.Data)) + { + adapterLogger.LogWarning(args.Data); + } } catch (Exception ex) { diff --git a/docs/protocol.md b/docs/protocol.md index 4e6f713..4469b20 100644 --- a/docs/protocol.md +++ b/docs/protocol.md @@ -320,7 +320,8 @@ In brief: `#!##!#`, or `{{error}}`. - `{{expected}}` as the command asks for the declared settings; `{{quit}}` ends the process. - Log lines go to standard error, starting with `{{log.information}}`, `{{log.warning}}` or - `{{log.error}}`. + `{{log.error}}`. Any other line there, such as dotnet's own reason for not starting the adapter, + is logged as a warning. - One call at a time. A timed-out call kills the process. New SDKs should implement protocol 2.