Skip to content

Commit 1fda3f2

Browse files
AnatoliBAnatoliB
authored
Log function script exception and error details (#328)
Log function script exception and error details
1 parent c842853 commit 1fda3f2

File tree

5 files changed

+231
-8
lines changed

5 files changed

+231
-8
lines changed

‎src/PowerShell/ErrorRecordFormatter.cs‎

Lines changed: 113 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,113 @@
1+
//
2+
// Copyright (c) Microsoft. All rights reserved.
3+
// Licensed under the MIT license. See LICENSE file in the project root for full license information.
4+
//
5+
6+
namespace Microsoft.Azure.Functions.PowerShellWorker.PowerShell
7+
{
8+
using System;
9+
using System.Linq;
10+
using System.Management.Automation;
11+
using System.Text;
12+
13+
internal class ErrorRecordFormatter
14+
{
15+
private const string TruncationPostfix = "...";
16+
private const string Indent = " ";
17+
18+
private readonly PowerShell _pwsh = PowerShell.Create();
19+
20+
/// <summary>
21+
/// maxSize limits the maximum size of the formatted error string (in characters).
22+
/// The rest will be truncated. This value should be high enough to allow the result
23+
/// contain the most important and relevant information, but low enough to create
24+
/// no problems for the communication channels used to propagate this data.
25+
/// The default value is somewhat arbitrary but satisfies both conditions.
26+
/// </summary>
27+
public string Format(ErrorRecord errorRecord, int maxSize = 1 * 1024 * 1024)
28+
{
29+
var errorDetails = _pwsh.AddCommand("Microsoft.PowerShell.Utility\\Out-String")
30+
.AddParameter("InputObject", errorRecord)
31+
.InvokeAndClearCommands<string>();
32+
33+
var result = new StringBuilder(
34+
capacity: Math.Min(1024, maxSize),
35+
maxCapacity: maxSize);
36+
37+
try
38+
{
39+
result.Append(errorDetails.Single());
40+
result.AppendLine("Script stack trace:");
41+
AppendStackTrace(result, errorRecord.ScriptStackTrace, Indent);
42+
result.AppendLine();
43+
44+
if (errorRecord.Exception != null)
45+
{
46+
AppendExceptionWithInners(result, errorRecord.Exception);
47+
}
48+
49+
return result.ToString();
50+
}
51+
catch (ArgumentOutOfRangeException) // exceeding StringBuilder max capacity
52+
{
53+
return Truncate(result, maxSize);
54+
}
55+
}
56+
57+
private static void AppendExceptionWithInners(StringBuilder result, Exception exception)
58+
{
59+
AppendExceptionInfo(result, exception);
60+
61+
if (exception is AggregateException aggregateException)
62+
{
63+
foreach (var innerException in aggregateException.Flatten().InnerExceptions)
64+
{
65+
AppendInnerExceptionIfNotNull(result, innerException);
66+
}
67+
}
68+
else
69+
{
70+
AppendInnerExceptionIfNotNull(result, exception.InnerException);
71+
}
72+
}
73+
74+
private static void AppendInnerExceptionIfNotNull(StringBuilder result, Exception innerException)
75+
{
76+
if (innerException != null)
77+
{
78+
result.Append("Inner exception: ");
79+
AppendExceptionWithInners(result, innerException);
80+
}
81+
}
82+
83+
private static void AppendExceptionInfo(StringBuilder stringBuilder, Exception exception)
84+
{
85+
stringBuilder.Append(exception.GetType().FullName);
86+
stringBuilder.Append(": ");
87+
stringBuilder.AppendLine(exception.Message);
88+
89+
AppendStackTrace(stringBuilder, exception.StackTrace, string.Empty);
90+
stringBuilder.AppendLine();
91+
}
92+
93+
private static void AppendStackTrace(StringBuilder stringBuilder, string stackTrace, string indent)
94+
{
95+
if (stackTrace != null)
96+
{
97+
stringBuilder.Append(indent);
98+
stringBuilder.AppendLine(stackTrace.Replace(Environment.NewLine, Environment.NewLine + indent));
99+
}
100+
}
101+
102+
private static string Truncate(StringBuilder result, int maxSize)
103+
{
104+
var charactersToRemove = result.Length + TruncationPostfix.Length - maxSize;
105+
if (charactersToRemove > 0)
106+
{
107+
result.Remove(result.Length - charactersToRemove, charactersToRemove);
108+
}
109+
110+
return result + TruncationPostfix;
111+
}
112+
}
113+
}

‎src/PowerShell/PowerShellManager.cs‎

Lines changed: 18 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -7,12 +7,10 @@
77
using System.Collections;
88
using System.Collections.Generic;
99
using System.Collections.ObjectModel;
10-
using System.IO;
1110
using System.Reflection;
1211

1312
using Microsoft.Azure.Functions.PowerShellWorker.Utility;
1413
using Microsoft.Azure.WebJobs.Script.Grpc.Messages;
15-
using System.Management.Automation.Runspaces;
1614
using LogLevel = Microsoft.Azure.WebJobs.Script.Grpc.Messages.RpcLog.Types.Level;
1715

1816
namespace Microsoft.Azure.Functions.PowerShellWorker.PowerShell
@@ -36,6 +34,8 @@ internal class PowerShellManager
3634
private readonly PowerShell _pwsh;
3735
private bool _runspaceInited;
3836

37+
private readonly ErrorRecordFormatter _errorRecordFormatter = new ErrorRecordFormatter();
38+
3939
/// <summary>
4040
/// Gets the Runspace InstanceId.
4141
/// </summary>
@@ -114,7 +114,7 @@ internal void Initialize()
114114
/// </summary>
115115
private void RegisterStreamEvents()
116116
{
117-
var streamHandler = new StreamHandler(_logger);
117+
var streamHandler = new StreamHandler(_logger, _errorRecordFormatter);
118118
_pwsh.Streams.Debug.DataAdding += streamHandler.DebugDataAdding;
119119
_pwsh.Streams.Error.DataAdding += streamHandler.ErrorDataAdding;
120120
_pwsh.Streams.Information.DataAdding += streamHandler.InformationDataAdding;
@@ -230,8 +230,16 @@ internal Hashtable InvokeFunction(
230230
_pwsh.AddParameter(AzFunctionInfo.TriggerMetadata, triggerMetadata);
231231
}
232232

233-
Collection<object> pipelineItems = _pwsh.AddCommand("Microsoft.Azure.Functions.PowerShellWorker\\Trace-PipelineObject")
234-
.InvokeAndClearCommands<object>();
233+
try
234+
{
235+
Collection<object> pipelineItems = _pwsh.AddCommand("Microsoft.Azure.Functions.PowerShellWorker\\Trace-PipelineObject")
236+
.InvokeAndClearCommands<object>();
237+
}
238+
catch (RuntimeException e)
239+
{
240+
Logger.Log(isUserOnlyLog: true, LogLevel.Error, GetFunctionExceptionMessage(e));
241+
throw;
242+
}
235243

236244
Hashtable result = new Hashtable(outputBindings, StringComparer.OrdinalIgnoreCase);
237245

@@ -281,5 +289,10 @@ private void ResetRunspace()
281289
// We should only remove the new global variables and does nothing else.
282290
Utils.CleanupGlobalVariables(_pwsh);
283291
}
292+
293+
private string GetFunctionExceptionMessage(IContainsErrorRecord exception)
294+
{
295+
return $"EXCEPTION: {_errorRecordFormatter.Format(exception.ErrorRecord)}";
296+
}
284297
}
285298
}

‎src/PowerShell/StreamHandler.cs‎

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -13,10 +13,12 @@ namespace Microsoft.Azure.Functions.PowerShellWorker.PowerShell
1313
internal class StreamHandler
1414
{
1515
ILogger _logger;
16+
private ErrorRecordFormatter _errorRecordFormatter;
1617

17-
public StreamHandler(ILogger logger)
18+
public StreamHandler(ILogger logger, ErrorRecordFormatter errorRecordFormatter)
1819
{
1920
_logger = logger;
21+
_errorRecordFormatter = errorRecordFormatter;
2022
}
2123

2224
public void DebugDataAdding(object sender, DataAddingEventArgs e)
@@ -31,7 +33,7 @@ public void ErrorDataAdding(object sender, DataAddingEventArgs e)
3133
{
3234
if(e.ItemAdded is ErrorRecord record)
3335
{
34-
_logger.Log(isUserOnlyLog: true, LogLevel.Error, $"ERROR: {record.Exception.Message}", record.Exception);
36+
_logger.Log(isUserOnlyLog: true, LogLevel.Error, $"ERROR: {_errorRecordFormatter.Format(record)}", record.Exception);
3537
}
3638
}
3739

‎test/Unit/PowerShell/ErrorRecordFormatterTests.cs‎

Lines changed: 94 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,94 @@
1+
//
2+
// Copyright (c) Microsoft. All rights reserved.
3+
// Licensed under the MIT license. See LICENSE file in the project root for full license information.
4+
//
5+
6+
namespace Microsoft.Azure.Functions.PowerShellWorker.Test
7+
{
8+
using System;
9+
using System.Linq;
10+
using System.Management.Automation;
11+
using System.Text.RegularExpressions;
12+
13+
using Xunit;
14+
15+
using Microsoft.Azure.Functions.PowerShellWorker.PowerShell;
16+
17+
public class ErrorRecordFormatterTests
18+
{
19+
private static readonly ErrorRecordFormatter s_errorRecordFormatter = new ErrorRecordFormatter();
20+
21+
[Fact]
22+
public void FormattedStringContainsBasicErrorRecordData()
23+
{
24+
var exception = new RuntimeException("My exception");
25+
var errorRecord = new ErrorRecord(exception, "error id", ErrorCategory.InvalidOperation, null);
26+
27+
var result = s_errorRecordFormatter.Format(errorRecord);
28+
29+
Assert.StartsWith(exception.Message, result);
30+
var resultLines = result.Split(Environment.NewLine);
31+
Assert.Contains(resultLines, line => Regex.IsMatch(line, @"\bCategoryInfo\b[:\s]*?\bInvalidOperation\b"));
32+
Assert.Contains(resultLines, line => Regex.IsMatch(line, @"\bFullyQualifiedErrorId\b[:\s]*?\berror id\b"));
33+
Assert.Contains(resultLines, line => line == "System.Management.Automation.RuntimeException: My exception");
34+
}
35+
36+
[Fact]
37+
public void FormattedStringContainsInnerExceptions()
38+
{
39+
var exception1 = new Exception("My exception 1");
40+
var exception2 = new Exception("My exception 2", exception1);
41+
var exception3 = new Exception("My exception 3", exception2);
42+
var errorRecord = new ErrorRecord(exception3, "error id", ErrorCategory.InvalidOperation, null);
43+
44+
var result = s_errorRecordFormatter.Format(errorRecord);
45+
46+
var resultLines = result.Split(Environment.NewLine);
47+
Assert.Contains(resultLines, line => line == "Inner exception: System.Exception: My exception 1");
48+
Assert.Contains(resultLines, line => line == "Inner exception: System.Exception: My exception 2");
49+
Assert.Equal(2, resultLines.Count(line => line.Contains("Inner exception:")));
50+
}
51+
52+
[Fact]
53+
public void FormattedStringContainsAggregateExceptionMembers()
54+
{
55+
var exception1 = new Exception("My exception 1");
56+
var exception2 = new Exception("My exception 2");
57+
var exception3 = new AggregateException("My exception 3", exception1, exception2);
58+
var exception4 = new Exception("My exception 4", exception3);
59+
var exception5 = new Exception("My exception 5");
60+
var exception6 = new AggregateException("My exception 6", exception4, exception5);
61+
var exception7 = new Exception("My exception 7", exception6);
62+
var errorRecord = new ErrorRecord(exception7, "error id", ErrorCategory.InvalidOperation, null);
63+
64+
var result = s_errorRecordFormatter.Format(errorRecord);
65+
66+
var resultLines = result.Split(Environment.NewLine);
67+
Assert.Contains(resultLines, line => line == "Inner exception: System.Exception: My exception 1");
68+
Assert.Contains(resultLines, line => line == "Inner exception: System.Exception: My exception 2");
69+
Assert.Contains(resultLines, line => line.StartsWith("Inner exception: System.AggregateException: My exception 3"));
70+
Assert.Contains(resultLines, line => line == "Inner exception: System.Exception: My exception 4");
71+
Assert.Contains(resultLines, line => line == "Inner exception: System.Exception: My exception 5");
72+
Assert.Contains(resultLines, line => line.StartsWith("Inner exception: System.AggregateException: My exception 6"));
73+
Assert.Contains(resultLines, line => line == "System.Exception: My exception 7");
74+
}
75+
76+
[Fact]
77+
public void FormattedStringIsTruncatedIfTooLong()
78+
{
79+
var exception1 = new Exception("My exception 1");
80+
var exception2 = new Exception("My exception 2", exception1);
81+
var exception3 = new Exception("My exception 3", exception2);
82+
var errorRecord = new ErrorRecord(exception3, "error id", ErrorCategory.InvalidOperation, null);
83+
var fullResult = s_errorRecordFormatter.Format(errorRecord);
84+
85+
var maxSize = fullResult.Length / 2;
86+
var truncatedResult = new ErrorRecordFormatter().Format(errorRecord, maxSize);
87+
88+
const string ExpectedPostfix = "...";
89+
Assert.InRange(truncatedResult.Length, ExpectedPostfix.Length + 1, maxSize);
90+
Assert.EndsWith(ExpectedPostfix, truncatedResult);
91+
Assert.StartsWith(fullResult.Substring(0, truncatedResult.Length - ExpectedPostfix.Length), truncatedResult);
92+
}
93+
}
94+
}

‎test/Unit/PowerShell/PowerShellManagerTests.cs‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -313,7 +313,8 @@ public void ProfileWithNonTerminatingError()
313313
testManager.InvokeProfile(profilePath);
314314

315315
Assert.Equal(2, s_testLogger.FullLog.Count);
316-
Assert.Equal("Error: ERROR: help me!", s_testLogger.FullLog[0]);
316+
Assert.StartsWith("Error: ERROR: ", s_testLogger.FullLog[0]);
317+
Assert.Contains("help me!", s_testLogger.FullLog[0]);
317318
Assert.Matches("Error: Fail to run profile.ps1. See logs for detailed errors. Profile location: ", s_testLogger.FullLog[1]);
318319
}
319320

0 commit comments

Comments
 (0)