Skip to content

Commit 0829b90

Browse files
authored
Improvements to FunctionLogs and Sanitize method. Addresses issues #2199, #2206, 2197 in V1 (#2239)
* Improvements to FunctionLogs and Sanitize method
1 parent 5fa02ca commit 0829b90

File tree

6 files changed

+119
-51
lines changed

6 files changed

+119
-51
lines changed

src/WebJobs.Script.WebHost/Diagnostics/EventGenerator.cs

Lines changed: 64 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -12,7 +12,7 @@ internal class EventGenerator : IEventGenerator
1212
{
1313
private const string EventTimestamp = "MM/dd/yyyy hh:mm:ss.fff tt";
1414

15-
public void LogFunctionTraceEvent(TraceLevel level, string subscriptionId, string appName, string functionName, string eventName, string source, string details, string summary)
15+
public void LogFunctionTraceEvent(TraceLevel level, string subscriptionId, string appName, string functionName, string eventName, string source, string details, string summary, string exceptionType, string exceptionMessage)
1616
{
1717
string eventTimestamp = DateTime.UtcNow.ToString(EventTimestamp);
1818
switch (level)
@@ -27,7 +27,7 @@ public void LogFunctionTraceEvent(TraceLevel level, string subscriptionId, strin
2727
FunctionsSystemLogsEventSource.Instance.RaiseFunctionsEventWarning(subscriptionId, appName, functionName, eventName, source, details, summary, ScriptHost.Version, eventTimestamp);
2828
break;
2929
case TraceLevel.Error:
30-
FunctionsSystemLogsEventSource.Instance.RaiseFunctionsEventError(subscriptionId, appName, functionName, eventName, source, details, summary, ScriptHost.Version, eventTimestamp);
30+
FunctionsSystemLogsEventSource.Instance.RaiseFunctionsEventError(subscriptionId, appName, functionName, eventName, source, details, summary, ScriptHost.Version, eventTimestamp, exceptionType, exceptionMessage);
3131
break;
3232
}
3333
}
@@ -148,7 +148,7 @@ protected void WriteEvent(int eventNum, string a, string b, int c, string d, str
148148
}
149149
}
150150

151-
// RaiseFunctionsEventVerbose/Info/Warning/Error
151+
// RaiseFunctionsEventVerbose/Info/Warning
152152
[NonEvent]
153153
protected void WriteEvent(int eventNum, string a, string b, string c, string d, string e, string f, string g, string h, string i)
154154
{
@@ -187,6 +187,50 @@ protected void WriteEvent(int eventNum, string a, string b, string c, string d,
187187
}
188188
}
189189

190+
// RaiseFunctionsEventError
191+
[NonEvent]
192+
protected void WriteEvent(int eventNum, string a, string b, string c, string d, string e, string f, string g, string h, string i, string j, string k)
193+
{
194+
const int count = 11;
195+
fixed (char* aPtr = a,
196+
bPtr = b,
197+
cPtr = c,
198+
dPtr = d,
199+
ePtr = e,
200+
fPtr = f,
201+
gPtr = g,
202+
hPtr = h,
203+
iPtr = i,
204+
jPtr = j,
205+
kPtr = k)
206+
{
207+
EventData* data = stackalloc EventData[count];
208+
data[0].DataPointer = (IntPtr)aPtr;
209+
data[0].Size = (a.Length + 1) * sizeof(char);
210+
data[1].DataPointer = (IntPtr)bPtr;
211+
data[1].Size = (b.Length + 1) * sizeof(char);
212+
data[2].DataPointer = (IntPtr)cPtr;
213+
data[2].Size = (c.Length + 1) * sizeof(char);
214+
data[3].DataPointer = (IntPtr)dPtr;
215+
data[3].Size = (d.Length + 1) * sizeof(char);
216+
data[4].DataPointer = (IntPtr)ePtr;
217+
data[4].Size = (e.Length + 1) * sizeof(char);
218+
data[5].DataPointer = (IntPtr)fPtr;
219+
data[5].Size = (f.Length + 1) * sizeof(char);
220+
data[6].DataPointer = (IntPtr)gPtr;
221+
data[6].Size = (g.Length + 1) * sizeof(char);
222+
data[7].DataPointer = (IntPtr)hPtr;
223+
data[7].Size = (h.Length + 1) * sizeof(char);
224+
data[8].DataPointer = (IntPtr)iPtr;
225+
data[8].Size = (i.Length + 1) * sizeof(char);
226+
data[9].DataPointer = (IntPtr)jPtr;
227+
data[9].Size = (j.Length + 1) * sizeof(char);
228+
data[10].DataPointer = (IntPtr)kPtr;
229+
data[10].Size = (k.Length + 1) * sizeof(char);
230+
WriteEventCore(eventNum, count, data);
231+
}
232+
}
233+
190234
// LogFunctionMetricEvent
191235
[NonEvent]
192236
protected void WriteEvent(int eventNum, string a, string b, string c, string d, long e, long f, long g, long h, string i, string j)
@@ -231,7 +275,7 @@ public class FunctionsEventSource : ExtendedEventSource
231275
{
232276
internal static readonly FunctionsEventSource Instance = new FunctionsEventSource();
233277

234-
[Event(57907, Level = EventLevel.Informational, Channel = EventChannel.Operational)]
278+
[Event(57907, Level = EventLevel.Informational, Channel = EventChannel.Operational, Keywords = FunctionsKeywords.DefaultMetricsKeyword)]
235279
public void LogFunctionExecutionAggregateEvent(string siteName, string functionName, ulong executionTimeInMs, ulong functionStartedCount, ulong functionCompletedCount, ulong functionFailedCount)
236280
{
237281
if (IsEnabled())
@@ -240,7 +284,7 @@ public void LogFunctionExecutionAggregateEvent(string siteName, string functionN
240284
}
241285
}
242286

243-
[Event(57908, Level = EventLevel.Informational, Channel = EventChannel.Operational)]
287+
[Event(57908, Level = EventLevel.Informational, Channel = EventChannel.Operational, Keywords = FunctionsKeywords.DefaultMetricsKeyword)]
244288
public void LogFunctionDetailsEvent(string siteName, string functionName, string inputBindings, string outputBindings, string scriptType, bool isDisabled)
245289
{
246290
if (IsEnabled())
@@ -249,23 +293,28 @@ public void LogFunctionDetailsEvent(string siteName, string functionName, string
249293
}
250294
}
251295

252-
[Event(57909, Level = EventLevel.Informational, Channel = EventChannel.Operational)]
296+
[Event(57909, Level = EventLevel.Informational, Channel = EventChannel.Operational, Keywords = FunctionsKeywords.DefaultMetricsKeyword)]
253297
public void LogFunctionExecutionEvent(string executionId, string siteName, int concurrency, string functionName, string invocationId, string executionStage, ulong executionTimeSpan, bool success)
254298
{
255299
if (IsEnabled())
256300
{
257301
WriteEvent(57909, executionId, siteName, concurrency, functionName, invocationId, executionStage, executionTimeSpan, success);
258302
}
259303
}
304+
305+
public class FunctionsKeywords
306+
{
307+
public const EventKeywords DefaultMetricsKeyword = unchecked((EventKeywords)0x8000000000000000);
308+
}
260309
}
261310

262311
[EventSource(Guid = "a7044dd6-c8ef-4980-858c-942d972b6250")]
263-
[SuppressMessage("Microsoft.StyleCop.CSharp.NamingRules", "SA1306:FieldNamesMustBeginWithLowerCaseLetter", Justification = "Need to use Pascal Case for MDS column names")]
312+
[SuppressMessage("Microsoft.StyleCop.CSharp.NamingRules", "SA1313:FieldNamesMustBeginWithLowerCaseLetter", Justification = "Need to use Pascal Case for MDS column names")]
264313
public class FunctionsSystemLogsEventSource : ExtendedEventSource
265314
{
266315
internal static readonly FunctionsSystemLogsEventSource Instance = new FunctionsSystemLogsEventSource();
267316

268-
[Event(65520, Level = EventLevel.Verbose, Channel = EventChannel.Operational, Version = 1)]
317+
[Event(65520, Level = EventLevel.Verbose, Channel = EventChannel.Operational, Version = 2)]
269318
public void RaiseFunctionsEventVerbose(string SubscriptionId, string AppName, string FunctionName, string EventName, string Source, string Details, string Summary, string HostVersion, string EventTimestamp)
270319
{
271320
if (IsEnabled())
@@ -274,7 +323,7 @@ public void RaiseFunctionsEventVerbose(string SubscriptionId, string AppName, st
274323
}
275324
}
276325

277-
[Event(65521, Level = EventLevel.Informational, Channel = EventChannel.Operational, Version = 1)]
326+
[Event(65521, Level = EventLevel.Informational, Channel = EventChannel.Operational, Version = 2)]
278327
public void RaiseFunctionsEventInfo(string SubscriptionId, string AppName, string FunctionName, string EventName, string Source, string Details, string Summary, string HostVersion, string EventTimestamp)
279328
{
280329
if (IsEnabled())
@@ -283,7 +332,7 @@ public void RaiseFunctionsEventInfo(string SubscriptionId, string AppName, strin
283332
}
284333
}
285334

286-
[Event(65522, Level = EventLevel.Warning, Channel = EventChannel.Operational, Version = 1)]
335+
[Event(65522, Level = EventLevel.Warning, Channel = EventChannel.Operational, Version = 2)]
287336
public void RaiseFunctionsEventWarning(string SubscriptionId, string AppName, string FunctionName, string EventName, string Source, string Details, string Summary, string HostVersion, string EventTimestamp)
288337
{
289338
if (IsEnabled())
@@ -292,16 +341,16 @@ public void RaiseFunctionsEventWarning(string SubscriptionId, string AppName, st
292341
}
293342
}
294343

295-
[Event(65523, Level = EventLevel.Error, Channel = EventChannel.Operational, Version = 1)]
296-
public void RaiseFunctionsEventError(string SubscriptionId, string AppName, string FunctionName, string EventName, string Source, string Details, string Summary, string HostVersion, string EventTimestamp)
344+
[Event(65523, Level = EventLevel.Error, Channel = EventChannel.Operational, Version = 2)]
345+
public void RaiseFunctionsEventError(string SubscriptionId, string AppName, string FunctionName, string EventName, string Source, string Details, string Summary, string HostVersion, string EventTimestamp, string InnerExceptionType, string InnerExceptionMessage)
297346
{
298347
if (IsEnabled())
299348
{
300-
WriteEvent(65523, SubscriptionId, AppName, FunctionName, EventName, Source, Details, Summary, HostVersion, EventTimestamp);
349+
WriteEvent(65523, SubscriptionId, AppName, FunctionName, EventName, Source, Details, Summary, HostVersion, EventTimestamp, InnerExceptionType, InnerExceptionMessage);
301350
}
302351
}
303352

304-
[Event(65524, Level = EventLevel.Informational, Channel = EventChannel.Operational, Version = 1)]
353+
[Event(65524, Level = EventLevel.Informational, Channel = EventChannel.Operational, Version = 2)]
305354
public void LogFunctionMetricEvent(string SubscriptionId, string AppName, string FunctionName, string EventName, long Average, long Minimum, long Maximum, long Count, string HostVersion, string EventTimestamp)
306355
{
307356
if (IsEnabled())
@@ -311,4 +360,4 @@ public void LogFunctionMetricEvent(string SubscriptionId, string AppName, string
311360
}
312361
}
313362
}
314-
}
363+
}

src/WebJobs.Script.WebHost/Diagnostics/IEventGenerator.cs

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,7 @@ namespace Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics
88
{
99
public interface IEventGenerator
1010
{
11-
void LogFunctionTraceEvent(TraceLevel level, string subscriptionId, string appName, string functionName, string eventName, string source, string details, string summary);
11+
void LogFunctionTraceEvent(TraceLevel level, string subscriptionId, string appName, string functionName, string eventName, string source, string details, string summary, string exceptionType, string exceptionMessage);
1212

1313
void LogFunctionMetricEvent(string subscriptionId, string appName, string functionName, string eventName, long average, long minimum, long maximum, long count, DateTime eventTimestamp);
1414

@@ -18,4 +18,4 @@ public interface IEventGenerator
1818

1919
void LogFunctionExecutionEvent(string executionId, string siteName, int concurrency, string functionName, string invocationId, string executionStage, long executionTimeSpan, bool success);
2020
}
21-
}
21+
}

src/WebJobs.Script.WebHost/Diagnostics/Sanitizer.cs

Lines changed: 19 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -12,7 +12,10 @@ namespace Microsoft.Azure.WebJobs.Logging
1212
internal static class Sanitizer
1313
{
1414
private const string SecretReplacement = "[Hidden Credential]";
15-
private static readonly char[] ValueTerminators = new char[] { '<', '"' };
15+
private static readonly char[] ValueTerminators = new char[] { '<', '"', '\'' };
16+
17+
// List of keywords that should not be replaced with [Hidden Credential]
18+
private static readonly string[] AllowedTokens = new string[] { "PublicKeyToken=" };
1619
private static readonly string[] CredentialTokens = new string[] { "Token=", "DefaultEndpointsProtocol=http", "AccountKey=", "Data Source=", "Server=", "Password=", "pwd=", "&amp;sig=", "SharedAccessKey=" };
1720

1821
/// <summary>
@@ -28,13 +31,25 @@ internal static string Sanitize(string input)
2831
}
2932

3033
string t = input;
34+
string inputWithAllowedTokensHidden = input;
35+
36+
// Remove any known safe strings from the input before looking for Credentials
37+
foreach (string allowedToken in AllowedTokens)
38+
{
39+
if (inputWithAllowedTokensHidden.Contains(allowedToken))
40+
{
41+
string hiddenString = new string('#', allowedToken.Length);
42+
inputWithAllowedTokensHidden = inputWithAllowedTokensHidden.Replace(allowedToken, hiddenString);
43+
}
44+
}
45+
3146
foreach (var token in CredentialTokens)
3247
{
3348
int startIndex = 0;
3449
while (true)
3550
{
3651
// search for the next token instance
37-
startIndex = t.IndexOf(token, startIndex, StringComparison.OrdinalIgnoreCase);
52+
startIndex = inputWithAllowedTokensHidden.IndexOf(token, startIndex, StringComparison.OrdinalIgnoreCase);
3853
if (startIndex == -1)
3954
{
4055
break;
@@ -44,10 +59,11 @@ internal static string Sanitize(string input)
4459
int credentialEnd = t.IndexOfAny(ValueTerminators, startIndex);
4560

4661
t = t.Substring(0, startIndex) + SecretReplacement + (credentialEnd != -1 ? t.Substring(credentialEnd) : string.Empty);
62+
inputWithAllowedTokensHidden = inputWithAllowedTokensHidden.Substring(0, startIndex) + SecretReplacement + (credentialEnd != -1 ? inputWithAllowedTokensHidden.Substring(credentialEnd) : string.Empty);
4763
}
4864
}
4965

5066
return t;
5167
}
5268
}
53-
}
69+
}

src/WebJobs.Script.WebHost/Diagnostics/SystemTraceWriter.cs

Lines changed: 31 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@
33

44
using System;
55
using System.Diagnostics;
6+
using System.Reflection;
67
using Microsoft.Azure.WebJobs.Host;
78
using Microsoft.Azure.WebJobs.Logging;
89
using Microsoft.Azure.WebJobs.Script.Config;
@@ -37,6 +38,8 @@ public override void Trace(TraceEvent traceEvent)
3738
string appName = _appName ?? string.Empty;
3839
string source = traceEvent.Source ?? string.Empty;
3940
string summary = Sanitizer.Sanitize(traceEvent.Message) ?? string.Empty;
41+
string innerExceptionType = string.Empty;
42+
string innerExceptionMessage = string.Empty;
4043

4144
// Apply any additional extended event info from the Properties bag
4245
string functionName = string.Empty;
@@ -71,9 +74,36 @@ public override void Trace(TraceEvent traceEvent)
7174
if (string.IsNullOrEmpty(details) && traceEvent.Exception != null)
7275
{
7376
details = Sanitizer.Sanitize(traceEvent.Exception.ToFormattedString());
77+
if (string.IsNullOrEmpty(functionName) && traceEvent.Exception is FunctionInvocationException fex)
78+
{
79+
functionName = string.IsNullOrEmpty(fex.MethodName) ? string.Empty : fex.MethodName.Replace("Host.Functions.", string.Empty);
80+
}
81+
Exception innerException = traceEvent.Exception.InnerException;
82+
while (innerException != null && innerException.InnerException != null)
83+
{
84+
innerException = innerException.InnerException;
85+
}
86+
if (innerException != null)
87+
{
88+
GetExceptionDetails(innerException, out innerExceptionType, out innerExceptionMessage);
89+
}
90+
else
91+
{
92+
GetExceptionDetails(traceEvent.Exception, out innerExceptionType, out innerExceptionMessage);
93+
}
7494
}
7595

76-
_eventGenerator.LogFunctionTraceEvent(traceEvent.Level, subscriptionId, appName, functionName, eventName, source, details, summary);
96+
_eventGenerator.LogFunctionTraceEvent(traceEvent.Level, subscriptionId, appName, functionName, eventName, source, details, summary, innerExceptionType, innerExceptionMessage);
97+
}
98+
99+
private static void GetExceptionDetails(Exception exception, out string exceptionType, out string exceptionMessage)
100+
{
101+
if (exception == null)
102+
{
103+
throw new ArgumentNullException(nameof(exception));
104+
}
105+
exceptionType = exception.GetType().ToString();
106+
exceptionMessage = Sanitizer.Sanitize(exception.Message) ?? string.Empty;
77107
}
78108
}
79109
}

test/WebJobs.Script.Tests.Integration/Host/WebScriptHostManagerTests.cs

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -454,7 +454,7 @@ public TestSystemEventGenerator()
454454

455455
public List<string> Events { get; private set; }
456456

457-
public void LogFunctionTraceEvent(TraceLevel level, string subscriptionId, string appName, string functionName, string eventName, string source, string details, string summary)
457+
public void LogFunctionTraceEvent(TraceLevel level, string subscriptionId, string appName, string functionName, string eventName, string source, string details, string summary, string exceptionType, string exceptionMessage)
458458
{
459459
var elements = new string[] { level.ToString(), subscriptionId, appName, functionName, eventName, source, summary, details };
460460
string evt = string.Join(" ", elements.Where(p => !string.IsNullOrEmpty(p)));

0 commit comments

Comments
 (0)