Log function script exception and error details

src/PowerShell/ErrorRecordFormatter.cs

@@ -0,0 +1,113 @@
+//
+// 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();
+
+        /// <summary>
+        /// 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.
+        /// </summary>
+        public string Format(ErrorRecord errorRecord, int maxSize = 1 * 1024 * 1024)
+        {
+            var errorDetails = _pwsh.AddCommand("Microsoft.PowerShell.Utility\\Out-String")
+                                    .AddParameter("InputObject", errorRecord)
+                                    .InvokeAndClearCommands<string>();
+
+            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;
+        }
+    }
+}

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();
+
         /// <summary>
         /// Gets the Runspace InstanceId.
         /// </summary>
@@ -114,7 +114,7 @@ internal void Initialize()
         /// </summary>
         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<object> pipelineItems = _pwsh.AddCommand("Microsoft.Azure.Functions.PowerShellWorker\\Trace-PipelineObject")
-                                                        .InvokeAndClearCommands<object>();
+                try
+                {
+                    Collection<object> pipelineItems = _pwsh.AddCommand("Microsoft.Azure.Functions.PowerShellWorker\\Trace-PipelineObject")
+                                                            .InvokeAndClearCommands<object>();
+                }
+                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)}";
+        }
     }
 }

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);
             }
         }
 

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);
+        }
+    }
+}

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]);
         }