Repeatable execution in C# by Mark Seemann
A C# example of Goldilogs.
This article is part of a series of articles about repeatable execution. The introductory article argued that if you've logged the impure actions that a system made, you have enough information to reproduce what happened. The previous article verified that for the example scenario, the impure actions were limited to reading the current time and interacting with the application database.
This article shows how to implement equivalent functionality in C#. You should be able to extrapolate from this to other object-oriented programming languages.
The code is available on GitHub.
Impure actions #
In the previous article I modelled impure actions as free monads. In C#, it'd be more idiomatic to use Dependency Injection. Model each impure interaction as an interface.
public interface IClock { DateTime GetCurrentDateTime(); }
The demo code demonstrates a single feature of a REST API and it only requires a single method on this interface to work. Following the Dependency Inversion Principle
This interface only defines a single method, because that's all the client code requires."clients [...] own the abstract interfaces"
Likewise, the client code only needs two methods to interact with the database:
public interface IReservationsRepository { IEnumerable<Reservation> ReadReservations(DateTime date); void Create(Reservation reservation); }
In the Haskell example code base, I also implemented GET for /reservations, but I forgot to do that here. There's only two methods on the interface: one to query the database, and one to create a new row.
Receive a reservation #
The central feature of the service is to receive and handle an HTTP POST request, as described in the introductory article. When a document arrives it triggers a series of non-trivial work:
- The service validates the input data. Among other things, it checks that the reservation is in the future. It uses
GetCurrentDateTimefor this. - It queries the database for existing reservations. It uses
ReadReservationsfor this. - It uses complex business logic to determine whether to accept the reservation. This essentially implements the Maître d' kata.
- If it accepts the reservation, it stores it. It uses
Createfor this.
public ActionResult Post(ReservationDto dto) { if (!DateTime.TryParse(dto.Date, out var _)) return BadRequest($"Invalid date: {dto.Date}."); Reservation reservation = Mapper.Map(dto); if (reservation.Date < Clock.GetCurrentDateTime()) return BadRequest($"Invalid date: {reservation.Date}."); var reservations = Repository.ReadReservations(reservation.Date); bool accepted = maîtreD.CanAccept(reservations, reservation); if (!accepted) return StatusCode(StatusCodes.Status500InternalServerError, "Couldn't accept."); Repository.Create(reservation); return Ok(); }
Clock and Repository are injected dependencies, and maîtreD is an object that implements the decision logic as the pure CanAccept function.
Composition #
The Post method is defined on a class called ReservationsController with these dependencies:
public ReservationsController( TimeSpan seatingDuration, IReadOnlyCollection<Table> tables, IReservationsRepository repository, IClock clock)
The seatingDuration and tables arguments are primitive dependencies used to configure the maîtreD object. I could also have injected maîtreD as a concrete dependency, but I decided against that for no particular reason.
There's no logging dependency, but the system still logs. Like in the previous example, logging is a cross-cutting concern and exclusively addressed through composition:
if (controllerType == typeof(ReservationsController)) { var l = new ScopedLog(new FileLog(LogFile)); var controller = new ReservationsController( SeatingDuration, Tables, new LogReservationsRepository( new SqlReservationsRepository(ConnectionString), l), new LogClock( new SystemClock(), l)); Logs.AddOrUpdate(controller, l, (_, x) => x); return controller; }
Each dependency is wrapped by a logger. We'll return to that in a minute, but consider first the actual implementations.
Using the system clock #
Using the system clock is easy:
public class SystemClock : IClock { public DateTime GetCurrentDateTime() { return DateTime.Now; } }
This implementation of IClock simply delegates to DateTime.Now. Again, no logging service is injected.
Using the database #
Using the database isn't much harder. I don't find that ORMs offer any benefits, so I prefer to implement database functionality using basic database APIs:
public void Create(Reservation reservation) { using (var conn = new SqlConnection(ConnectionString)) using (var cmd = new SqlCommand(createReservationSql, conn)) { cmd.Parameters.Add( new SqlParameter("@Guid", reservation.Id)); cmd.Parameters.Add( new SqlParameter("@Date", reservation.Date)); cmd.Parameters.Add( new SqlParameter("@Name", reservation.Name)); cmd.Parameters.Add( new SqlParameter("@Email", reservation.Email)); cmd.Parameters.Add( new SqlParameter("@Quantity", reservation.Quantity)); conn.Open(); cmd.ExecuteNonQuery(); } } private const string createReservationSql = @" INSERT INTO [dbo].[Reservations] ([Guid], [Date], [Name], [Email], [Quantity]) OUTPUT INSERTED.Id VALUES (@Guid, @Date, @Name, @Email, @Quantity)";
The above code snippet implements the Create method of the IReservationsRepository interface. Please refer to the Git repository for the full code if you need more details.
If you prefer to implement your database functionality with an ORM, or in another way, you can do that. It doesn't change the architecture of the system. No logging service is required to interact with the database.
Compose with logging #
As the above composition code snippet suggests, logging is implemented with Decorators. The ultimate implementation of IClock is SystemClock, but the Composition Root decorates it with LogClock:
public class LogClock : IClock { public LogClock(IClock inner, ScopedLog log) { Inner = inner; Log = log; } public IClock Inner { get; } public ScopedLog Log { get; } public DateTime GetCurrentDateTime() { var currentDateTime = Inner.GetCurrentDateTime(); Log.Observe( new Interaction { Operation = nameof(GetCurrentDateTime), Output = currentDateTime }); return currentDateTime; } }
ScopedLog is a Concrete Dependency that, among other members, affords the Observe method. Notice that LogClock implements IClock by decorating another polymorphic IClock instance. It delegates functionality to inner, logs the currentDateTime and returns it.
The LogReservationsRepository class implements the same pattern:
public class LogReservationsRepository : IReservationsRepository { public LogReservationsRepository(IReservationsRepository inner, ScopedLog log) { Inner = inner; Log = log; } public IReservationsRepository Inner { get; } public ScopedLog Log { get; } public void Create(Reservation reservation) { Log.Observe( new Interaction { Operation = nameof(Create), Input = new { reservation } }); Inner.Create(reservation); } public IEnumerable<Reservation> ReadReservations(DateTime date) { var reservations = Inner.ReadReservations(date); Log.Observe( new Interaction { Operation = nameof(ReadReservations), Input = new { date }, Output = reservations }); return reservations; } }
This architecture not only implements the desired functionality, but also Goldilogs: not too little, not too much, but just what you need. Notice that I didn't have to change any of my Domain Model or HTTP-specific code to enable logging. This cross-cutting concern is enabled entirely via composition.
Repeatability #
An HTTP request like this:
POST /reservations/ HTTP/1.1
Content-Type: application/json
{
"id": "7bc3fc93-a777-4138-8630-a805e7246335",
"date": "2020-03-20 18:45:00",
"name": "Kozue Kaburagi",
"email": "ninjette@example.net",
"quantity": 4
}
produces a log entry like this:
{
"entry": {
"time": "2020-01-02T09:50:34.2678703+01:00",
"operation": "Post",
"input": {
"dto": {
"id": "7bc3fc93-a777-4138-8630-a805e7246335",
"date": "2020-03-20 18:45:00",
"email": "ninjette@example.net",
"name": "Kozue Kaburagi",
"quantity": 4
}
},
"output": null
},
"interactions": [
{
"time": "2020-01-02T09:50:34.2726143+01:00",
"operation": "GetCurrentDateTime",
"input": null,
"output": "2020-01-02T09:50:34.2724012+01:00"
},
{
"time": "2020-01-02T09:50:34.3571224+01:00",
"operation": "ReadReservations",
"input": { "date": "2020-03-20T18:45:00" },
"output": [
{
"id": "c3cbfbc7-6d64-4ead-84ef-7f89de5b7e1c",
"date": "2020-03-20T19:00:00",
"email": "emp@example.com",
"name": "Elissa Megan Powers",
"quantity": 3
}
]
},
{
"time": "2020-01-02T09:50:34.3587586+01:00",
"operation": "Create",
"input": {
"reservation": {
"id": "7bc3fc93-a777-4138-8630-a805e7246335",
"date": "2020-03-20T18:45:00",
"email": "ninjette@example.net",
"name": "Kozue Kaburagi",
"quantity": 4
}
},
"output": null
}
],
"exit": {
"time": "2020-01-02T09:50:34.3645105+01:00",
"operation": null,
"input": null,
"output": { "statusCode": 200 }
}
}
I chose to gather all information regarding a single HTTP request into a single log entry and format it as JSON. I once worked with an organisation that used the ELK stack in that way, and it made it easy to identify and troubleshoot issues in production.
You can use such a log file to reproduce the observed behaviour, for example in a unit test:
[Fact] public void NinjetteRepro() { string log = Log.LoadFile("Ninjette.json"); (ReservationsController sut, ReservationDto dto) = Log.LoadReservationsControllerPostScenario(log); var actual = sut.Post(dto); Assert.IsAssignableFrom<OkResult>(actual); }
This test reproduces the behaviour that was recorded in the above JSON log. While there was already one existing reservation (returned from ReadReservations), the system had enough remaining capacity to accept the new reservation. Therefore, the expected result is an OkResult.
Replay #
You probably noticed the helper methods Log.LoadFile and Log.LoadReservationsControllerPostScenario. This API is just a prototype to get the point across. There's little to say about LoadFile, since it just reads the file. The LoadReservationsControllerPostScenario method performs the bulk of the work. It parses the JSON string into a collection of observations. It then feeds these observations to test-specific implementations of the dependencies required by ReservationsController.
For example, here's the test-specific implementation of IClock:
public class ReplayClock : IClock { private readonly Queue<DateTime> times; public ReplayClock(IEnumerable<DateTime> times) { this.times = new Queue<DateTime>(times); } public DateTime GetCurrentDateTime() { return times.Dequeue(); } }
The above JSON log example only contains a single observation of GetCurrentDateTime, but an arbitrary log may contain zero, one, or several observations. The idea is to replay them, starting with the earliest. ReplayClock just creates a Queue of them and Dequeue every time GetCurrentDateTime executes.
The test-specific ReplayReservationsRepository class works the same way:
public class ReplayReservationsRepository : IReservationsRepository { private readonly IDictionary<DateTime, Queue<IEnumerable<Reservation>>> reads; public ReplayReservationsRepository( IDictionary<DateTime, Queue<IEnumerable<Reservation>>> reads) { this.reads = reads; } public void Create(Reservation reservation) { } public IEnumerable<Reservation> ReadReservations(DateTime date) { return reads[date].Dequeue(); } }
You'll notice that in order to implement ReadReservations, the ReplayReservationsRepository class needs a dictionary of queues. The ReplayClock class didn't need a dictionary, because GetCurrentDateTime takes no input. The ReadReservations method, on the other hand, takes a date as a method argument. You might have observations of ReadReservations for different dates, and multiple observations for each date. That's the reason that ReplayReservationsRepository needs a dictionary of queues.
The Create method doesn't return anything, so I decided that this methods should do nothing.
The LoadReservationsControllerPostScenario function parses the JSON log and creates instances of these Test Doubles.
var repository = new ReplayReservationsRepository(reads); var clock = new ReplayClock(times); var controller = new ReservationsController(seatingDuration, tables, repository, clock);
And that, together with the parsed HTTP input, is what LoadReservationsControllerPostScenario returns:
return (controller, dto);
This is only a prototype to illustrate the point that you can reproduce an interaction if you have all the impure inputs and outputs. The details are available in the source code repository.
Summary #
This article demonstrated how making the distinction between pure and impure code is useful in many situations. For logging purposes, you only need to log the impure inputs and outputs. That's neither too little logging, nor too much, but just right: Goldilogs.
Model any (potentially) impure interaction as a dependency and use Dependency Injection. This enables you to reproduce observed behaviour from logs. Don't inject logging services into your Controllers or Domain Models.
