From 0ab22fe51e67cebc1e8469c2677989f096aa0815 Mon Sep 17 00:00:00 2001 From: Bec Callow Date: Tue, 6 Oct 2026 12:16:27 +1000 Subject: [PATCH] Log the Web Deploy error when an Azure Web App (Web Deploy) deployment fails The NetCoreShim logged the exception without its inner exceptions (the output template has no {Exception} token) and wrote it to stdout, while NetCoreWebDeploymentExecutor built its exception from stderr. Failed deployments therefore logged "Retry #n on Azure deploy. Exception:" and a bare System.Exception with no message. The shim now writes Error and Fatal lines to stderr and logs each inner exception's message, and the executor uses those lines as the exception message. Output lines without a level prefix are logged at verbose instead of being dropped. Co-Authored-By: Claude Opus 5.5 --- .../Program.cs | 37 +++++++- .../NetCoreWebDeploymentExecutorFixture.cs | 90 +++++++++++++++++++ .../NetCoreWebDeploymentExecutor.cs | 36 +++++++- 3 files changed, 159 insertions(+), 4 deletions(-) create mode 100644 source/Calamari.AzureWebApp.Tests/NetCoreWebDeploymentExecutorFixture.cs 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; } }