diff --git a/source/Calamari.AzureWebApp.NetCoreShim/Program.cs b/source/Calamari.AzureWebApp.NetCoreShim/Program.cs index 046f16019..d2fe2ee8b 100644 --- a/source/Calamari.AzureWebApp.NetCoreShim/Program.cs +++ b/source/Calamari.AzureWebApp.NetCoreShim/Program.cs @@ -1,8 +1,10 @@ using System; using System.Collections.Generic; +using System.Linq; using System.Threading.Tasks; using CommandLine; using Serilog; +using Serilog.Events; using Serilog.Sinks.SystemConsole.Themes; namespace Calamari.AzureWebApp.NetCoreShim @@ -53,7 +55,10 @@ public static async Task Main(string[] args) { var logger = new LoggerConfiguration() .MinimumLevel.Verbose() - .WriteTo.Console(outputTemplate: "{Level:u3}|{Message:lj}{NewLine}", theme: ConsoleTheme.None) + // Errors go to stderr so that Calamari can report them as the reason the deployment failed + .WriteTo.Console(outputTemplate: "{Level:u3}|{Message:lj}{NewLine}", + theme: ConsoleTheme.None, + standardErrorFromLevel: LogEventLevel.Error) .CreateLogger(); return await Parser.Default.ParseArguments(args) @@ -67,11 +72,39 @@ public static async Task Main(string[] args) } catch (Exception e) { - logger.Error(e, e.Message); + LogException(logger, e); return 1; } }, err => Task.FromResult(1)); } + + // Calamari reads our output one line at a time and only understands lines that start with a level prefix, + // so the exception is written line by line rather than through the output template's {Exception} token. + // Web Deploy puts the real cause in the inner exceptions, so each one's message is logged as an error. + static void LogException(ILogger logger, Exception exception) + { + string previous = null; + for (var ex = exception; ex != null; ex = ex.InnerException) + { + var firstLine = SplitLines(ex.Message).FirstOrDefault(); + if (!string.IsNullOrWhiteSpace(firstLine) && firstLine != previous) + { + logger.Error("{Line:l}", firstLine); + } + + previous = firstLine; + } + + foreach (var line in SplitLines(exception.ToString())) + { + logger.Verbose("{Line:l}", line); + } + } + + static IEnumerable SplitLines(string text) + { + return (text ?? string.Empty).Split(new[] { "\r\n", "\n" }, StringSplitOptions.RemoveEmptyEntries); + } } } \ No newline at end of file diff --git a/source/Calamari.AzureWebApp.Tests/NetCoreWebDeploymentExecutorFixture.cs b/source/Calamari.AzureWebApp.Tests/NetCoreWebDeploymentExecutorFixture.cs new file mode 100644 index 000000000..b45bffdb7 --- /dev/null +++ b/source/Calamari.AzureWebApp.Tests/NetCoreWebDeploymentExecutorFixture.cs @@ -0,0 +1,90 @@ +using System; +using Calamari.Common.Plumbing.FileSystem; +using Calamari.Testing.Helpers; +using NUnit.Framework; + +namespace Calamari.AzureWebApp.Tests; + +[TestFixture] +public class NetCoreWebDeploymentExecutorFixture +{ + [Test] + [Category("PlatformAgnostic")] + public void FailureMessageContainsTheErrorsTheShimReportedWithoutTheirLevel() + { + var errorOutput = "ERR|(6/10/2026 10:59:25 AM) An error occurred when the request was processed on the remote computer." + Environment.NewLine + + "ERR|An error was encountered when processing operation 'Delete File' on 'index.html'. ---> System.IO.IOException: Invalid access to memory location." + Environment.NewLine; + + var message = NetCoreWebDeploymentExecutor.FailureMessage(1, errorOutput); + + Assert.That(message, + Is.EqualTo("(6/10/2026 10:59:25 AM) An error occurred when the request was processed on the remote computer." + + Environment.NewLine + + "An error was encountered when processing operation 'Delete File' on 'index.html'. ---> System.IO.IOException: Invalid access to memory location.")); + } + + [Test] + [Category("PlatformAgnostic")] + public void FailureMessageDoesNotRepeatAnError() + { + var errorOutput = "ERR|An error occurred when the request was processed on the remote computer." + Environment.NewLine + + "ERR|An error occurred when the request was processed on the remote computer." + Environment.NewLine; + + Assert.That(NetCoreWebDeploymentExecutor.FailureMessage(1, errorOutput), + Is.EqualTo("An error occurred when the request was processed on the remote computer.")); + } + + [Test] + [Category("PlatformAgnostic")] + public void FailureMessageKeepsStdErrThatWasNotWrittenByTheShimLogger() + { + var errorOutput = "Unhandled Exception: System.IO.FileNotFoundException: Could not load file or assembly 'Microsoft.Web.Deployment'" + Environment.NewLine; + + Assert.That(NetCoreWebDeploymentExecutor.FailureMessage(1, errorOutput), + Is.EqualTo("Unhandled Exception: System.IO.FileNotFoundException: Could not load file or assembly 'Microsoft.Web.Deployment'")); + } + + [TestCase(null)] + [TestCase("")] + [TestCase("\r\n")] + [Category("PlatformAgnostic")] + public void FailureMessageIsNotEmptyWhenTheShimReportedNoErrors(string errorOutput) + { + Assert.That(NetCoreWebDeploymentExecutor.FailureMessage(1, errorOutput), + Does.StartWith("Calamari.AzureWebApp.NetCoreShim.exe exited with code 1")); + } + + [Test] + [Category("PlatformAgnostic")] + public void LogsEachLevelAtTheMatchingLevel() + { + var log = new InMemoryLog(); + var executor = new NetCoreWebDeploymentExecutor(log, CalamariPhysicalFileSystem.GetPhysicalFileSystem()); + + executor.LogOutputMessage("VRB|verbose"); + executor.LogOutputMessage("DBG|debug"); + executor.LogOutputMessage("INF|info"); + executor.LogOutputMessage("WRN|warning"); + executor.LogOutputMessage("ERR|error"); + executor.LogOutputMessage("FTL|fatal"); + executor.LogOutputMessage("INF|RESULT|{}"); + + Assert.That(log.MessagesVerboseFormatted, Is.EqualTo(new[] { "verbose", "debug" })); + Assert.That(log.MessagesInfoFormatted, Is.EqualTo(new[] { "info" })); + Assert.That(log.MessagesWarnFormatted, Is.EqualTo(new[] { "warning" })); + Assert.That(log.MessagesErrorFormatted, Is.EqualTo(new[] { "error", "fatal" })); + } + + [Test] + [Category("PlatformAgnostic")] + public void LinesWithoutAKnownLevelAreLoggedInsteadOfDropped() + { + var log = new InMemoryLog(); + var executor = new NetCoreWebDeploymentExecutor(log, CalamariPhysicalFileSystem.GetPhysicalFileSystem()); + + executor.LogOutputMessage(" at Microsoft.Web.Deployment.DeploymentAgent.HandleSync()"); + executor.LogOutputMessage("XYZ|unknown level"); + + Assert.That(log.MessagesVerboseFormatted, Is.EqualTo(new[] { " at Microsoft.Web.Deployment.DeploymentAgent.HandleSync()", "XYZ|unknown level" })); + } +} diff --git a/source/Calamari.AzureWebApp/NetCoreWebDeploymentExecutor.cs b/source/Calamari.AzureWebApp/NetCoreWebDeploymentExecutor.cs index e89f0f98a..2030887d2 100644 --- a/source/Calamari.AzureWebApp/NetCoreWebDeploymentExecutor.cs +++ b/source/Calamari.AzureWebApp/NetCoreWebDeploymentExecutor.cs @@ -20,6 +20,7 @@ namespace Calamari.AzureWebApp public class NetCoreWebDeploymentExecutor : IWebDeploymentExecutor { const string ToolName = "Calamari.AzureWebApp.NetCoreShim.exe"; + static readonly string[] LevelPrefixes = { "VRB|", "DBG|", "INF|", "WRN|", "ERR|", "FTL|" }; readonly ILog log; readonly ICalamariFileSystem fileSystem; @@ -92,7 +93,7 @@ public async Task ExecuteDeployment(RunningDeployment deployment, AzureTargetSit //if there was an error, we just blow up here as we will have written the errors in the above file if (commandResult.ExitCode != 0) { - throw new Exception(commandResult.ErrorOutput); + throw new Exception(FailureMessage(commandResult.ExitCode, commandResult.ErrorOutput)); } if (resultMessage == null) @@ -137,9 +138,37 @@ public async Task ExecuteDeployment(RunningDeployment deployment, AzureTargetSit } } - void LogOutputMessage(string msg) + // The shim writes its errors to stderr, each line prefixed with its level + internal static string FailureMessage(int exitCode, string errorOutput) + { + var errors = (errorOutput ?? string.Empty) + .Split(new[] { "\r\n", "\n" }, StringSplitOptions.RemoveEmptyEntries) + .Select(StripLevelPrefix) + .Where(line => !string.IsNullOrWhiteSpace(line)) + .Distinct() + .ToArray(); + + return errors.Length > 0 + ? string.Join(Environment.NewLine, errors) + : $"{ToolName} exited with code {exitCode} without reporting an error. Check the verbose log for details."; + } + + static string StripLevelPrefix(string line) + { + var prefix = LevelPrefixes.FirstOrDefault(p => line.StartsWith(p, StringComparison.Ordinal)); + return prefix == null ? line : line[prefix.Length..]; + } + + internal void LogOutputMessage(string msg) { var firstIndex = msg.IndexOf("|", StringComparison.Ordinal); + if (firstIndex < 0) + { + // Not written by the shim's logger (e.g. a runtime error), so there is no level to go by + log.Verbose(msg); + return; + } + var level = msg[..firstIndex]; var message = msg[(firstIndex + 1)..]; @@ -165,6 +194,9 @@ void LogOutputMessage(string msg) case "FTL": log.Error(message); break; + default: + log.Verbose(msg); + break; } }