AWS examples in C# – structured logging in .NET Core and AWS Lambda

Last Updated on by

Post summary: Code examples of how to do structured logging in .NET Core and C# AWS Lambda.

This post is part of AWS examples in C# – working with SQS, DynamoDB, Lambda, ECS series. The code used for this series of blog posts is located in aws.examples.csharp GitHub repository.

Structured logging

In the general case, log files are a big text file with no structure in it. This makes it hard to search and analyze log files. The idea of structured logging is to write log files into a given format, such as JSON or XML, so they can later be machine processed such search or big data analysis. In the current post, I will describe how to log in to JSON format. For e.g. one log entry is:

[12:17:16 INF] New Movie published with Die Hard, {"Title": "Die Hard", "Genre": "Action", "$type": "Movie"}

This is a simple text with the Movie object being input as JSON. In order to process it, a parser has to be implemented, which gets the data into the square brackets and extracts the date-time and the log level, then searching into the content itself is hard because it should be done with lots of regular expressions. With structured logging the same entity will look like this:

{
	"@t": "2020-03-29T10:21:24.2907688Z",
	"@mt": "New Movie published with {Title}, {@Content}",
	"Title": "Die Hard",
	"Content": {
		"Title": "Die Hard",
		"Genre": "Action",
		"$type": "Movie"
	},
	"SourceContext": "SqsWriter.Controllers.PublishController",
	"ActionId": "20de3310-ebce-48d5-8f9c-28914e199937",
	"ActionName": "SqsWriter.Controllers.PublishController.PublishMovie (SqsWriter)",
	"RequestId": "0HLUJPBNDGPSJ:00000001",
	"RequestPath": "/api/publish/movie",
	"SpanId": "|7bab219a-415f5c121e1756f5.",
	"TraceId": "7bab219a-415f5c121e1756f5",
	"ParentId": "",
	"ConnectionId": "0HLUJPBNDGPSJ"
}

There is much more data in the latter and it is also in JSON format which makes it easy to search with JsonPath.

JSON Path

JsonPath is a way to navigate into a JSON document, very similar to XPath for XML. With JSONPath Online Evaluator is easy to try some expressions. Both $.Content.Title and $.Title resolves to Die Hard. So it is very easy for a tool that understands the JsonPath to query logs where some JSON entity is related somehow to a given rule, for e.g. $.Title equals to Die Hard.

AWS CloudWatch

CloudWatch provides different monitoring functions, one of them is logging. By default, all AWS services log into CloudWatch. CloudWatch provides a feature called insights which is able to search into JSON log files.

Serilog

Serilog is a .NET library that provides logging capabilities. Its main benefits are that it can log into JSON format. Serilog can be very easily integrated into any C# project. Two Nuget packages are needed: Serilog and Serilog.AspNetCore.

Configure Serilog for .NET Core application

In the case of .NET Core microservice Serilog is injected into Program.cs.

using Serilog;
using Serilog.Events;
using Serilog.Formatting.Compact;

public static void Main(string[] args)
{
	Log.Logger = new LoggerConfiguration()
		.MinimumLevel.Debug()
		.MinimumLevel.Override("Microsoft", LogEventLevel.Warning)
		.Enrich.FromLogContext()
		.WriteTo.Console(new CompactJsonFormatter())
		.CreateLogger();

	var webHost = WebHost.CreateDefaultBuilder(args)
		.UseStartup<Startup>()
		.UseSerilog()
		.UseUrls("http://*:5100")
		.Build();

	webHost.Run();
}

Configure Serilog for AWS C# Lambda function

In the case of C# lambda function, logging to console is enough, since all logs are sent to CloudWatch. I have created a proxy class called Logger, which instantiates an instance of Serilog logger. The custom logger is then used in lambda function itself.

Logger

public interface ILogger
{
	void LogInformation(string messageTemplate, params object[] arguments);
}

public class Logger : ILogger
{
	private static Serilog.Core.Logger _logger;

	public Logger()
	{
		_logger = new LoggerConfiguration()
			.MinimumLevel.Debug()
			.WriteTo.Console(new CompactJsonFormatter())
			.CreateLogger();
	}

	public void LogInformation(string messageTemplate, params object[] arguments)
	{
		_logger.Information(messageTemplate, arguments);
	}
}

MoviesFunction

private readonly ISqsWriter _sqsWriter;
private readonly IDynamoDbWriter _dynamoDbWriter;
private readonly ILogger _logger;

public MoviesFunction() : this(null, null, null) { }

public MoviesFunction(ISqsWriter sqsWriter, IDynamoDbWriter dynamoDbWriter, ILogger logger)
{
	_sqsWriter = sqsWriter ?? new SqsWriter();
	_dynamoDbWriter = dynamoDbWriter ?? new DynamoDbWriter();
	_logger = logger ?? new Logger();
}

public async Task MoviesFunctionHandler(DynamoDBEvent dynamoEvent, ILambdaContext context)
{
	foreach (var record in dynamoEvent.Records)
	{
		var title = record.Dynamodb.NewImage["Title"].S;
		var logEntry = new LogEntry
		{
			Message = $"Movie '{title}' processed by lambda",
			DateTime = DateTime.Now
		};
		_logger.LogInformation("MoviesFunctionHandler invoked with {Title}", title);

		await _sqsWriter.WriteLogEntryAsync(logEntry);
		await _dynamoDbWriter.PutLogEntryAsync(logEntry);
	}
}

GetMovie

public async Task<APIGatewayProxyResponse> GetMovie(APIGatewayProxyRequest request, ILambdaContext context)
{
	var title = WebUtility.UrlDecode(request.PathParameters["title"]);
	_logger.LogInformation("GetMovie invoked with {Title}", title);

	var document = await _dynamoDbReader.GetDocumentAsync(TableName, title);
	if (document == null)
	{
		_logger.LogInformation("GetMovie produced no results for {Title}", title);
		return new APIGatewayProxyResponse { StatusCode = (int)HttpStatusCode.NotFound };
	}

	var movie = new Movie
	{
		Title = document["Title"],
		Genre = (MovieGenre)int.Parse(document["Genre"])
	};
	_logger.LogInformation("GetMovie result is {Title}, {@Content}", movie.Title, movie);

	return new APIGatewayProxyResponse
	{
		StatusCode = (int)HttpStatusCode.OK,
		Body = _jsonConverter.SerializeObject(movie)
	};
}

AWS CloudWatch Insights

CloudWatch Logs Insights enables interactive search and analyze log data in Amazon CloudWatch Logs. Queries can be performed to help more efficiently and effectively respond to operational issues. Queries are done in a specific purpose-built query language with a few simple but powerful commands. A short example is to search for all logs in which FirstName field equals Bruce. Before that all log groups that has to be searched are selected above.

fields @@mt
| sort @timestamp desc
| limit 20
| filter FirstName = 'Bruce'

An extensive guide on query language can be found on CloudWatch Logs Insights Query Syntax page.

Conclusion

Structured logging can bring a lot of benefits to debugging an application and analyzing its behavior. It is easy to set up and be used.

Related Posts

Category: C#, Tutorials | Tags: