From bb6b46280f08a3b693e13bb2f2b08db762ff2bf0 Mon Sep 17 00:00:00 2001 From: Anatoli Beliaev Date: Mon, 16 Sep 2019 12:50:23 -0700 Subject: [PATCH 1/3] Log function script exception and error details --- src/PowerShell/ErrorRecordFormatter.cs | 106 ++++++++++++++++++ src/PowerShell/PowerShellManager.cs | 23 +++- src/PowerShell/StreamHandler.cs | 6 +- .../PowerShell/ErrorRecordFormatterTests.cs | 94 ++++++++++++++++ .../Unit/PowerShell/PowerShellManagerTests.cs | 3 +- 5 files changed, 224 insertions(+), 8 deletions(-) create mode 100644 src/PowerShell/ErrorRecordFormatter.cs create mode 100644 test/Unit/PowerShell/ErrorRecordFormatterTests.cs diff --git a/src/PowerShell/ErrorRecordFormatter.cs b/src/PowerShell/ErrorRecordFormatter.cs new file mode 100644 index 00000000..80239cb6 --- /dev/null +++ b/src/PowerShell/ErrorRecordFormatter.cs @@ -0,0 +1,106 @@ +// +// Copyright (c) Microsoft. All rights reserved. +// Licensed under the MIT license. See LICENSE file in the project root for full license information. +// + +namespace Microsoft.Azure.Functions.PowerShellWorker.PowerShell +{ + using System; + using System.Linq; + using System.Management.Automation; + using System.Text; + + internal class ErrorRecordFormatter + { + private const string TruncationPostfix = "..."; + private const string Indent = " "; + + private readonly PowerShell _pwsh = PowerShell.Create(); + + public string Format(ErrorRecord errorRecord, int maxSize = 1 * 1024 * 1024) + { + var errorDetails = _pwsh.AddCommand("Out-String") + .AddParameter("InputObject", errorRecord) + .InvokeAndClearCommands(); + + var result = new StringBuilder( + capacity: Math.Min(1024, maxSize), + maxCapacity: maxSize); + + try + { + result.Append(errorDetails.Single()); + result.AppendLine("Script stack trace:"); + AppendStackTrace(result, errorRecord.ScriptStackTrace, Indent); + result.AppendLine(); + + if (errorRecord.Exception != null) + { + AppendExceptionWithInners(result, errorRecord.Exception); + } + + return result.ToString(); + } + catch (ArgumentOutOfRangeException) // exceeding StringBuilder max capacity + { + return Truncate(result, maxSize); + } + } + + private static void AppendExceptionWithInners(StringBuilder result, Exception exception) + { + AppendExceptionInfo(result, exception); + + if (exception is AggregateException aggregateException) + { + foreach (var innerException in aggregateException.Flatten().InnerExceptions) + { + AppendInnerExceptionIfNotNull(result, innerException); + } + } + else + { + AppendInnerExceptionIfNotNull(result, exception.InnerException); + } + } + + private static void AppendInnerExceptionIfNotNull(StringBuilder result, Exception innerException) + { + if (innerException != null) + { + result.Append("Inner exception: "); + AppendExceptionWithInners(result, innerException); + } + } + + private static void AppendExceptionInfo(StringBuilder stringBuilder, Exception exception) + { + stringBuilder.Append(exception.GetType().FullName); + stringBuilder.Append(": "); + stringBuilder.AppendLine(exception.Message); + + AppendStackTrace(stringBuilder, exception.StackTrace, string.Empty); + stringBuilder.AppendLine(); + } + + private static void AppendStackTrace(StringBuilder stringBuilder, string stackTrace, string indent) + { + if (stackTrace != null) + { + stringBuilder.Append(indent); + stringBuilder.AppendLine(stackTrace.Replace(Environment.NewLine, Environment.NewLine + indent)); + } + } + + private static string Truncate(StringBuilder result, int maxSize) + { + var charactersToRemove = result.Length + TruncationPostfix.Length - maxSize; + if (charactersToRemove > 0) + { + result.Remove(result.Length - charactersToRemove, charactersToRemove); + } + + return result + TruncationPostfix; + } + } +} diff --git a/src/PowerShell/PowerShellManager.cs b/src/PowerShell/PowerShellManager.cs index 2180be2c..e35ec1c5 100644 --- a/src/PowerShell/PowerShellManager.cs +++ b/src/PowerShell/PowerShellManager.cs @@ -7,12 +7,10 @@ using System.Collections; using System.Collections.Generic; using System.Collections.ObjectModel; -using System.IO; using System.Reflection; using Microsoft.Azure.Functions.PowerShellWorker.Utility; using Microsoft.Azure.WebJobs.Script.Grpc.Messages; -using System.Management.Automation.Runspaces; using LogLevel = Microsoft.Azure.WebJobs.Script.Grpc.Messages.RpcLog.Types.Level; namespace Microsoft.Azure.Functions.PowerShellWorker.PowerShell @@ -36,6 +34,8 @@ internal class PowerShellManager private readonly PowerShell _pwsh; private bool _runspaceInited; + private readonly ErrorRecordFormatter _errorRecordFormatter = new ErrorRecordFormatter(); + /// /// Gets the Runspace InstanceId. /// @@ -114,7 +114,7 @@ internal void Initialize() /// private void RegisterStreamEvents() { - var streamHandler = new StreamHandler(_logger); + var streamHandler = new StreamHandler(_logger, _errorRecordFormatter); _pwsh.Streams.Debug.DataAdding += streamHandler.DebugDataAdding; _pwsh.Streams.Error.DataAdding += streamHandler.ErrorDataAdding; _pwsh.Streams.Information.DataAdding += streamHandler.InformationDataAdding; @@ -230,8 +230,16 @@ internal Hashtable InvokeFunction( _pwsh.AddParameter(AzFunctionInfo.TriggerMetadata, triggerMetadata); } - Collection pipelineItems = _pwsh.AddCommand("Microsoft.Azure.Functions.PowerShellWorker\\Trace-PipelineObject") - .InvokeAndClearCommands(); + try + { + Collection pipelineItems = _pwsh.AddCommand("Microsoft.Azure.Functions.PowerShellWorker\\Trace-PipelineObject") + .InvokeAndClearCommands(); + } + catch (RuntimeException e) + { + Logger.Log(isUserOnlyLog: true, LogLevel.Error, GetFunctionExceptionMessage(e)); + throw; + } Hashtable result = new Hashtable(outputBindings, StringComparer.OrdinalIgnoreCase); @@ -281,5 +289,10 @@ private void ResetRunspace() // We should only remove the new global variables and does nothing else. Utils.CleanupGlobalVariables(_pwsh); } + + private string GetFunctionExceptionMessage(IContainsErrorRecord exception) + { + return $"EXCEPTION: {_errorRecordFormatter.Format(exception.ErrorRecord)}"; + } } } diff --git a/src/PowerShell/StreamHandler.cs b/src/PowerShell/StreamHandler.cs index 466fa5e7..cec15fcf 100644 --- a/src/PowerShell/StreamHandler.cs +++ b/src/PowerShell/StreamHandler.cs @@ -13,10 +13,12 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.PowerShell internal class StreamHandler { ILogger _logger; + private ErrorRecordFormatter _errorRecordFormatter; - public StreamHandler(ILogger logger) + public StreamHandler(ILogger logger, ErrorRecordFormatter errorRecordFormatter) { _logger = logger; + _errorRecordFormatter = errorRecordFormatter; } public void DebugDataAdding(object sender, DataAddingEventArgs e) @@ -31,7 +33,7 @@ public void ErrorDataAdding(object sender, DataAddingEventArgs e) { if(e.ItemAdded is ErrorRecord record) { - _logger.Log(isUserOnlyLog: true, LogLevel.Error, $"ERROR: {record.Exception.Message}", record.Exception); + _logger.Log(isUserOnlyLog: true, LogLevel.Error, $"ERROR: {_errorRecordFormatter.Format(record)}", record.Exception); } } diff --git a/test/Unit/PowerShell/ErrorRecordFormatterTests.cs b/test/Unit/PowerShell/ErrorRecordFormatterTests.cs new file mode 100644 index 00000000..0946e8db --- /dev/null +++ b/test/Unit/PowerShell/ErrorRecordFormatterTests.cs @@ -0,0 +1,94 @@ +// +// Copyright (c) Microsoft. All rights reserved. +// Licensed under the MIT license. See LICENSE file in the project root for full license information. +// + +namespace Microsoft.Azure.Functions.PowerShellWorker.Test +{ + using System; + using System.Linq; + using System.Management.Automation; + using System.Text.RegularExpressions; + + using Xunit; + + using Microsoft.Azure.Functions.PowerShellWorker.PowerShell; + + public class ErrorRecordFormatterTests + { + private static readonly ErrorRecordFormatter s_errorRecordFormatter = new ErrorRecordFormatter(); + + [Fact] + public void FormattedStringContainsBasicErrorRecordData() + { + var exception = new RuntimeException("My exception"); + var errorRecord = new ErrorRecord(exception, "error id", ErrorCategory.InvalidOperation, null); + + var result = s_errorRecordFormatter.Format(errorRecord); + + Assert.StartsWith(exception.Message, result); + var resultLines = result.Split(Environment.NewLine); + Assert.Contains(resultLines, line => Regex.IsMatch(line, @"\bCategoryInfo\b[:\s]*?\bInvalidOperation\b")); + Assert.Contains(resultLines, line => Regex.IsMatch(line, @"\bFullyQualifiedErrorId\b[:\s]*?\berror id\b")); + Assert.Contains(resultLines, line => line == "System.Management.Automation.RuntimeException: My exception"); + } + + [Fact] + public void FormattedStringContainsInnerExceptions() + { + var exception1 = new Exception("My exception 1"); + var exception2 = new Exception("My exception 2", exception1); + var exception3 = new Exception("My exception 3", exception2); + var errorRecord = new ErrorRecord(exception3, "error id", ErrorCategory.InvalidOperation, null); + + var result = s_errorRecordFormatter.Format(errorRecord); + + var resultLines = result.Split(Environment.NewLine); + Assert.Contains(resultLines, line => line == "Inner exception: System.Exception: My exception 1"); + Assert.Contains(resultLines, line => line == "Inner exception: System.Exception: My exception 2"); + Assert.Equal(2, resultLines.Count(line => line.Contains("Inner exception:"))); + } + + [Fact] + public void FormattedStringContainsAggregateExceptionMembers() + { + var exception1 = new Exception("My exception 1"); + var exception2 = new Exception("My exception 2"); + var exception3 = new AggregateException("My exception 3", exception1, exception2); + var exception4 = new Exception("My exception 4", exception3); + var exception5 = new Exception("My exception 5"); + var exception6 = new AggregateException("My exception 6", exception4, exception5); + var exception7 = new Exception("My exception 7", exception6); + var errorRecord = new ErrorRecord(exception7, "error id", ErrorCategory.InvalidOperation, null); + + var result = s_errorRecordFormatter.Format(errorRecord); + + var resultLines = result.Split(Environment.NewLine); + Assert.Contains(resultLines, line => line == "Inner exception: System.Exception: My exception 1"); + Assert.Contains(resultLines, line => line == "Inner exception: System.Exception: My exception 2"); + Assert.Contains(resultLines, line => line.StartsWith("Inner exception: System.AggregateException: My exception 3")); + Assert.Contains(resultLines, line => line == "Inner exception: System.Exception: My exception 4"); + Assert.Contains(resultLines, line => line == "Inner exception: System.Exception: My exception 5"); + Assert.Contains(resultLines, line => line.StartsWith("Inner exception: System.AggregateException: My exception 6")); + Assert.Contains(resultLines, line => line == "System.Exception: My exception 7"); + } + + [Fact] + public void FormattedStringIsTruncatedIfTooLong() + { + var exception1 = new Exception("My exception 1"); + var exception2 = new Exception("My exception 2", exception1); + var exception3 = new Exception("My exception 3", exception2); + var errorRecord = new ErrorRecord(exception3, "error id", ErrorCategory.InvalidOperation, null); + var fullResult = s_errorRecordFormatter.Format(errorRecord); + + var maxSize = fullResult.Length / 2; + var truncatedResult = new ErrorRecordFormatter().Format(errorRecord, maxSize); + + const string ExpectedPostfix = "..."; + Assert.InRange(truncatedResult.Length, ExpectedPostfix.Length + 1, maxSize); + Assert.EndsWith(ExpectedPostfix, truncatedResult); + Assert.StartsWith(fullResult.Substring(0, truncatedResult.Length - ExpectedPostfix.Length), truncatedResult); + } + } +} diff --git a/test/Unit/PowerShell/PowerShellManagerTests.cs b/test/Unit/PowerShell/PowerShellManagerTests.cs index bd05bae3..1f5d7482 100644 --- a/test/Unit/PowerShell/PowerShellManagerTests.cs +++ b/test/Unit/PowerShell/PowerShellManagerTests.cs @@ -313,7 +313,8 @@ public void ProfileWithNonTerminatingError() testManager.InvokeProfile(profilePath); Assert.Equal(2, s_testLogger.FullLog.Count); - Assert.Equal("Error: ERROR: help me!", s_testLogger.FullLog[0]); + Assert.StartsWith("Error: ERROR: ", s_testLogger.FullLog[0]); + Assert.Contains("help me!", s_testLogger.FullLog[0]); Assert.Matches("Error: Fail to run profile.ps1. See logs for detailed errors. Profile location: ", s_testLogger.FullLog[1]); } From aadb5384285431e9d3fbb4ea69dca658670f05bc Mon Sep 17 00:00:00 2001 From: Anatoli Beliaev Date: Tue, 17 Sep 2019 10:59:36 -0700 Subject: [PATCH 2/3] Use full name when invoking Out-String --- src/PowerShell/ErrorRecordFormatter.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/PowerShell/ErrorRecordFormatter.cs b/src/PowerShell/ErrorRecordFormatter.cs index 80239cb6..194e1fef 100644 --- a/src/PowerShell/ErrorRecordFormatter.cs +++ b/src/PowerShell/ErrorRecordFormatter.cs @@ -19,7 +19,7 @@ internal class ErrorRecordFormatter public string Format(ErrorRecord errorRecord, int maxSize = 1 * 1024 * 1024) { - var errorDetails = _pwsh.AddCommand("Out-String") + var errorDetails = _pwsh.AddCommand("Microsoft.PowerShell.Utility\\Out-String") .AddParameter("InputObject", errorRecord) .InvokeAndClearCommands(); From f0b9961c91fb0c7854dfb491378e9f9a56f1a55c Mon Sep 17 00:00:00 2001 From: Anatoli Beliaev Date: Tue, 17 Sep 2019 11:51:39 -0700 Subject: [PATCH 3/3] Add a comment on maxSize --- src/PowerShell/ErrorRecordFormatter.cs | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/src/PowerShell/ErrorRecordFormatter.cs b/src/PowerShell/ErrorRecordFormatter.cs index 194e1fef..b82b6e90 100644 --- a/src/PowerShell/ErrorRecordFormatter.cs +++ b/src/PowerShell/ErrorRecordFormatter.cs @@ -17,6 +17,13 @@ internal class ErrorRecordFormatter private readonly PowerShell _pwsh = PowerShell.Create(); + /// + /// maxSize limits the maximum size of the formatted error string (in characters). + /// The rest will be truncated. This value should be high enough to allow the result + /// contain the most important and relevant information, but low enough to create + /// no problems for the communication channels used to propagate this data. + /// The default value is somewhat arbitrary but satisfies both conditions. + /// public string Format(ErrorRecord errorRecord, int maxSize = 1 * 1024 * 1024) { var errorDetails = _pwsh.AddCommand("Microsoft.PowerShell.Utility\\Out-String")