Skip to content

Amazon.Lambda.Logging.AspNetCore create parameterized JSON log messages #2083

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Draft
wants to merge 1 commit into
base: dev
Choose a base branch
from
Draft

Amazon.Lambda.Logging.AspNetCore create parameterized JSON log messages #2083

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
32 changes: 32 additions & 0 deletions .autover/changes/5e73fa84-6603-4a1e-b957-2e1e926c5aa9.json
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,32 @@
{
"Projects": [
{
"Name": "Amazon.Lambda.AspNetCoreServer",
"Type": "Minor",
"ChangelogMessages": [
"Update Amazon.Lambda.Logging.AspNetCore dependency"
]
},
{
"Name": "Amazon.Lambda.AspNetCoreServer.Hosting",
"Type": "Minor",
"ChangelogMessages": [
"Update Amazon.Lambda.Logging.AspNetCore dependency"
]
},
{
"Name": "Amazon.Lambda.Core",
"Type": "Minor",
"ChangelogMessages": [
"Added log level with exception version of the static logging functions on Amazon.Lambda.Core.LambdaLogger"
]
},
{
"Name": "Amazon.Lambda.Logging.AspNetCore",
"Type": "Minor",
"ChangelogMessages": [
"Convert logging parameters into JSON properties when Lambda log format is configured as JSON"
]
}
]
}
6 changes: 0 additions & 6 deletions Libraries/src/Amazon.Lambda.Core/LambdaLogger.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -75,10 +75,6 @@ private static void LogWithLevelAndExceptionToConsole(string level, Exception ex
Console.WriteLine(exception);
}

private const string ParameterizedPreviewMessage =
"This method has been mark as preview till the Lambda .NET Managed runtime has been updated with the backing implementation of this method. " +
"It is possible to use this method while in preview if the Lambda function is deployed as an executable and uses the latest version of Amazon.Lambda.RuntimeSupport.";

/// <summary>
/// Logs a message to AWS CloudWatch Logs.
///
Expand Down Expand Up @@ -114,7 +110,6 @@ public static void Log(string level, string message, params object[] args)
/// <param name="exception">Exception to include with the logging.</param>
/// <param name="message">Message to log. The message may have format arguments.</param>
/// <param name="args">Arguments to format the message with.</param>
[RequiresPreviewFeatures(ParameterizedPreviewMessage)]
public static void Log(string level, Exception exception, string message, params object[] args)
{
_loggingWithLevelAndExceptionAction(level, exception, message, args);
Expand All @@ -130,7 +125,6 @@ public static void Log(string level, Exception exception, string message, params
/// <param name="exception">Exception to include with the logging.</param>
/// <param name="message">Message to log. The message may have format arguments.</param>
/// <param name="args">Arguments to format the message with.</param>
[RequiresPreviewFeatures(ParameterizedPreviewMessage)]
public static void Log(LogLevel level, Exception exception, string message, params object[] args) => Log(level.ToString(), exception, message, args);
#endif
}
Expand Down
86 changes: 58 additions & 28 deletions Libraries/src/Amazon.Lambda.Logging.AspNetCore/LambdaILogger.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -52,39 +52,61 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
return;
}

var components = new List<string>(4);
if (_options.IncludeLogLevel)
{
components.Add($"[{logLevel}]");
}

GetScopeInformation(components);
var lambdaLogLevel = ConvertLogLevel(logLevel);

if (_options.IncludeCategory)
if (IsLambdaJsonFormatEnabled && state is IEnumerable<KeyValuePair<string, object>> structure)
{
components.Add($"{_categoryName}:");
string messageTemplate = null;
var parameters = new List<object>();
foreach (var property in structure)
{
if (property is { Key: "{OriginalFormat}", Value: string value })
{
messageTemplate = value;
}
else
{
parameters.Add(property.Value);
}
}

Amazon.Lambda.Core.LambdaLogger.Log(lambdaLogLevel, exception, messageTemplate, parameters.ToArray());
}
if (_options.IncludeEventId)
else
{
components.Add($"[{eventId}]:");
}
var components = new List<string>(4);
if (_options.IncludeLogLevel)
{
components.Add($"[{logLevel}]");
}

var text = formatter.Invoke(state, exception);
components.Add(text);
GetScopeInformation(components);

if (_options.IncludeException)
{
components.Add($"{exception}");
}
if (_options.IncludeNewline)
{
components.Add(Environment.NewLine);
}
if (_options.IncludeCategory)
{
components.Add($"{_categoryName}:");
}
if (_options.IncludeEventId)
{
components.Add($"[{eventId}]:");
}

var finalText = string.Join(" ", components);
var text = formatter.Invoke(state, exception);
components.Add(text);

var lambdaLogLevel = ConvertLogLevel(logLevel);
Amazon.Lambda.Core.LambdaLogger.Log(lambdaLogLevel, finalText);
if (_options.IncludeException)
{
components.Add($"{exception}");
}
if (_options.IncludeNewline)
{
components.Add(Environment.NewLine);
}

var finalText = string.Join(" ", components);

Amazon.Lambda.Core.LambdaLogger.Log(lambdaLogLevel, finalText);
}
}

private static Amazon.Lambda.Core.LogLevel ConvertLogLevel(LogLevel logLevel)
Expand Down Expand Up @@ -126,9 +148,17 @@ private void GetScopeInformation(List<string> logMessageComponents)
logMessageComponents.Add("=>");
}
}
}

// Private classes
}

private bool IsLambdaJsonFormatEnabled
{
get
{
return string.Equals(Environment.GetEnvironmentVariable("AWS_LAMBDA_LOG_FORMAT"), "JSON", StringComparison.InvariantCultureIgnoreCase);
}
}

// Private classes
private class NoOpDisposable : IDisposable
{
public void Dispose()
Expand Down
96 changes: 74 additions & 22 deletions Libraries/test/Amazon.Lambda.Logging.AspNetCore.Tests/LoggingTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -118,14 +118,14 @@ public void TestWilcardConfiguration()
Assert.False(loggerOptions.IncludeLogLevel);
Assert.False(loggerOptions.IncludeNewline);

var loggerfactory = new TestLoggerFactory()
var loggerFactory = new TestLoggerFactory()
.AddLambdaLogger(loggerOptions);

int count = 0;

// Should match:
// "Foo.*": "Information"
var foobarLogger = loggerfactory.CreateLogger("Foo.Bar");
var foobarLogger = loggerFactory.CreateLogger("Foo.Bar");
foobarLogger.LogTrace(SHOULD_NOT_APPEAR);
foobarLogger.LogDebug(SHOULD_NOT_APPEAR);
foobarLogger.LogInformation(SHOULD_APPEAR + (count++));
Expand All @@ -135,7 +135,7 @@ public void TestWilcardConfiguration()

// Should match:
// "Foo.Bar.Baz": "Critical"
var foobarbazLogger = loggerfactory.CreateLogger("Foo.Bar.Baz");
var foobarbazLogger = loggerFactory.CreateLogger("Foo.Bar.Baz");
foobarbazLogger.LogTrace(SHOULD_NOT_APPEAR);
foobarbazLogger.LogDebug(SHOULD_NOT_APPEAR);
foobarbazLogger.LogInformation(SHOULD_NOT_APPEAR);
Expand All @@ -145,7 +145,7 @@ public void TestWilcardConfiguration()

// Should match:
// "Foo.Bar.*": "Warning"
var foobarbuzzLogger = loggerfactory.CreateLogger("Foo.Bar.Buzz");
var foobarbuzzLogger = loggerFactory.CreateLogger("Foo.Bar.Buzz");
foobarbuzzLogger.LogTrace(SHOULD_NOT_APPEAR);
foobarbuzzLogger.LogDebug(SHOULD_NOT_APPEAR);
foobarbuzzLogger.LogInformation(SHOULD_NOT_APPEAR);
Expand All @@ -156,7 +156,7 @@ public void TestWilcardConfiguration()

// Should match:
// "*": "Error"
var somethingLogger = loggerfactory.CreateLogger("something");
var somethingLogger = loggerFactory.CreateLogger("something");
somethingLogger.LogTrace(SHOULD_NOT_APPEAR);
somethingLogger.LogDebug(SHOULD_NOT_APPEAR);
somethingLogger.LogInformation(SHOULD_NOT_APPEAR);
Expand Down Expand Up @@ -285,19 +285,19 @@ public void TestLoggingExceptionsAndEvents()
.Build();

var loggerOptions = new LambdaLoggerOptions(configuration);
var loggerfactory = new TestLoggerFactory()
var loggerFactory = new TestLoggerFactory()
.AddLambdaLogger(loggerOptions);

int countMessage = 0;
int countEvent = 0;
int countException = 0;

var defaultLogger = loggerfactory.CreateLogger("Default");
var defaultLogger = loggerFactory.CreateLogger("Default");
defaultLogger.LogTrace(SHOULD_NOT_APPEAR_EVENT, SHOULD_NOT_APPEAR_EXCEPTION, SHOULD_NOT_APPEAR);
defaultLogger.LogDebug(SHOULD_NOT_APPEAR_EVENT, SHOULD_APPEAR + (countMessage++));
defaultLogger.LogCritical(SHOULD_NOT_APPEAR_EVENT, SHOULD_APPEAR + (countMessage++));

defaultLogger = loggerfactory.CreateLogger(null);
defaultLogger = loggerFactory.CreateLogger(null);
defaultLogger.LogTrace(SHOULD_NOT_APPEAR_EVENT, SHOULD_NOT_APPEAR);
defaultLogger.LogDebug(SHOULD_NOT_APPEAR_EVENT, SHOULD_APPEAR + (countMessage++));
defaultLogger.LogCritical(SHOULD_NOT_APPEAR_EVENT, SHOULD_APPEAR + (countMessage++));
Expand All @@ -309,12 +309,12 @@ public void TestLoggingExceptionsAndEvents()
loggerOptions.IncludeException = true;
loggerOptions.IncludeEventId = true;

var msLogger = loggerfactory.CreateLogger("Microsoft");
var msLogger = loggerFactory.CreateLogger("Microsoft");
msLogger.LogTrace(SHOULD_NOT_APPEAR_EVENT, SHOULD_NOT_APPEAR_EXCEPTION, SHOULD_NOT_APPEAR);
msLogger.LogInformation(GET_SHOULD_APPEAR_EVENT(countEvent++), GET_SHOULD_APPEAR_EXCEPTION(countException++), SHOULD_APPEAR + (countMessage++));
msLogger.LogCritical(GET_SHOULD_APPEAR_EVENT(countEvent++), GET_SHOULD_APPEAR_EXCEPTION(countException++), SHOULD_APPEAR + (countMessage++));

var sdkLogger = loggerfactory.CreateLogger("AWSSDK");
var sdkLogger = loggerFactory.CreateLogger("AWSSDK");
sdkLogger.LogTrace(SHOULD_NOT_APPEAR_EVENT, SHOULD_NOT_APPEAR_EXCEPTION, SHOULD_NOT_APPEAR);
sdkLogger.LogInformation(GET_SHOULD_APPEAR_EVENT(countEvent++), GET_SHOULD_APPEAR_EXCEPTION(countException++), SHOULD_APPEAR + (countMessage++));
sdkLogger.LogCritical(GET_SHOULD_APPEAR_EVENT(countEvent++), GET_SHOULD_APPEAR_EXCEPTION(countException++), SHOULD_APPEAR + (countMessage++));
Expand Down Expand Up @@ -356,10 +356,10 @@ public void TestLoggingScopesEvents()
ConnectLoggingActionToLogger(message => writer.Write(message));

var loggerOptions = new LambdaLoggerOptions{ IncludeScopes = true };
var loggerfactory = new TestLoggerFactory()
var loggerFactory = new TestLoggerFactory()
.AddLambdaLogger(loggerOptions);

var defaultLogger = loggerfactory.CreateLogger("Default");
var defaultLogger = loggerFactory.CreateLogger("Default");

// Act
using(defaultLogger.BeginScope("First {0}", "scope123"))
Expand Down Expand Up @@ -391,10 +391,10 @@ public void TestLoggingScopesEvents_When_ScopesDisabled()
ConnectLoggingActionToLogger(message => writer.Write(message));

var loggerOptions = new LambdaLoggerOptions { IncludeScopes = false };
var loggerfactory = new TestLoggerFactory()
var loggerFactory = new TestLoggerFactory()
.AddLambdaLogger(loggerOptions);

var defaultLogger = loggerfactory.CreateLogger("Default");
var defaultLogger = loggerFactory.CreateLogger("Default");

// Act
using (defaultLogger.BeginScope("First {0}", "scope123"))
Expand Down Expand Up @@ -477,25 +477,25 @@ public void TestDefaultLogLevel()
.Build();

var loggerOptions = new LambdaLoggerOptions(configuration);
var loggerfactory = new TestLoggerFactory()
var loggerFactory = new TestLoggerFactory()
.AddLambdaLogger(loggerOptions);

// act
// creating named logger, `Default` category is set to "Debug"
// (Default category has special treatment - it's not actually stored, named logger just falls to default)
var defaultLogger = loggerfactory.CreateLogger("Default");
var defaultLogger = loggerFactory.CreateLogger("Default");
defaultLogger.LogTrace(SHOULD_NOT_APPEAR);
defaultLogger.LogDebug(SHOULD_APPEAR);
defaultLogger.LogInformation(SHOULD_APPEAR);

// `Dummy` category is not specified, we should use `Default` category instead
var dummyLogger = loggerfactory.CreateLogger("Dummy");
var dummyLogger = loggerFactory.CreateLogger("Dummy");
dummyLogger.LogTrace(SHOULD_NOT_APPEAR);
dummyLogger.LogDebug(SHOULD_APPEAR);
dummyLogger.LogInformation(SHOULD_APPEAR);

// `Microsoft` category is specified, log accordingly
var msLogger = loggerfactory.CreateLogger("Microsoft");
var msLogger = loggerFactory.CreateLogger("Microsoft");
msLogger.LogTrace(SHOULD_NOT_APPEAR);
msLogger.LogDebug(SHOULD_NOT_APPEAR);
msLogger.LogInformation(SHOULD_APPEAR);
Expand All @@ -519,18 +519,18 @@ public void TestDefaultLogLevelIfNotConfigured()
.Build();

var loggerOptions = new LambdaLoggerOptions(configuration);
var loggerfactory = new TestLoggerFactory()
var loggerFactory = new TestLoggerFactory()
.AddLambdaLogger(loggerOptions);

// act
// `Dummy` category is not specified, we should stick with default: min level = INFO
var dummyLogger = loggerfactory.CreateLogger("Dummy");
var dummyLogger = loggerFactory.CreateLogger("Dummy");
dummyLogger.LogTrace(SHOULD_NOT_APPEAR);
dummyLogger.LogDebug(SHOULD_NOT_APPEAR);
dummyLogger.LogInformation(SHOULD_APPEAR);

// `Microsoft` category is specified, log accordingly
var msLogger = loggerfactory.CreateLogger("Microsoft");
var msLogger = loggerFactory.CreateLogger("Microsoft");
msLogger.LogTrace(SHOULD_NOT_APPEAR);
msLogger.LogDebug(SHOULD_NOT_APPEAR);
msLogger.LogInformation(SHOULD_NOT_APPEAR);
Expand All @@ -541,7 +541,47 @@ public void TestDefaultLogLevelIfNotConfigured()
}
}

private static string GetAppSettingsPath(string fileName)
/// <summary>
/// For this test we just need to make sure the _loggingWithLevelAndExceptionAction is called with parameters and exception.
/// We can't confirm the JSON formatting is done because RuntimeSupport is not involved. That is okay because we have
/// other tests that confirm RuntimeSupport formats the log as JSON. We jsut need to confirm the right callback is called
/// with the parameters from the log message.
/// </summary>
[Fact]
public void TestJSONParameterLogging()
{
Environment.SetEnvironmentVariable("AWS_LAMBDA_LOG_FORMAT", "JSON");
try
{
using (var writer = new StringWriter())
{
ConnectLoggingActionToLogger(message => writer.Write(message));

var configuration = new ConfigurationBuilder()
.AddJsonFile(GetAppSettingsPath("appsettings.json"))
.Build();

var loggerOptions = new LambdaLoggerOptions(configuration);
var loggerFactory = new TestLoggerFactory()
.AddLambdaLogger(loggerOptions);

var logger = loggerFactory.CreateLogger("JSONLogging");

logger.LogError(new Exception("Too Cheap"), "User {name} fail to by {product} for {price}", "Gilmour", "Guitar", 55.55);

var text = writer.ToString();
Assert.Contains("parameter count: 3", text);
Assert.Contains("Too Cheap", text);
}
}
finally
{
Environment.SetEnvironmentVariable("AWS_LAMBDA_LOG_FORMAT", null);
}

}

private static string GetAppSettingsPath(string fileName)
{
return Path.Combine(APPSETTINGS_DIR, fileName);
}
Expand All @@ -567,6 +607,18 @@ private static void ConnectLoggingActionToLogger(Action<string> loggingAction)
Assert.NotNull(loggingActionField);

loggingWithLevelActionField.SetValue(null, loggingWithLevelAction);

Action<string, Exception, string, object[]> loggingWithExceptionLevelAction = (level, exception, message, parameters) => {
var formattedMessage = $"{level}: {message}: parameter count: {parameters?.Length}\n{exception.Message}";
loggingAction(formattedMessage);
};

var loggingWithExceptionLevelActionField = lambdaLoggerType
.GetTypeInfo()
.GetField("_loggingWithLevelAndExceptionAction", BindingFlags.NonPublic | BindingFlags.Static);
Assert.NotNull(loggingActionField);

loggingWithExceptionLevelActionField.SetValue(null, loggingWithExceptionLevelAction);
}

private static int CountOccurences(string text, string substring)
Expand Down