dotnet
[API Proposal]: Extend FakeLogCollector with waiting capabilities
Latest proposal version
Background and motivation
Sometimes you don't know the exact moment in testing when a log will be recorded, particularly if it's part of a background job or something similar, or for convenience you may use it to assert if something has finished before carrying out further assertions.
API Proposal
public class FakeLogCollector
{
/*
... existing APIs ...
public void Clear()
public IReadOnlyList<FakeLogRecord> GetSnapshot(bool clear = false)
public FakeLogRecord LatestRecord
public int Count
*/
public IAsyncEnumerable<FakeLogRecord> GetLogsAsync(CancellationToken cancellationToken = default)
}
Behavior and usage
- Each enumerator always starts the iteration from the beginning of the currently stored (in memory) logs.
- In order to await a state of logs that come strictly after a certain known state and to not miss any logs coming in between the known state and the newly started wait, the caller needs to track an index of the previously known state, make sure not to clear the logs and skip the known count of logs during the new iteration. The asserting/waiting condition is then applied only to the logs coming after the previously known state.
- Using a shared enumerator across these waiting instances is also an option and not requiring to track indexes, re-iterating and skipping, but the usage of timeout-based cancellation logic becomes problematic, especially for net462 which does not support token reset.
With a library such as System.Linq.Async the caller can also do for example the following, which is expected to be among the more common scenarios:
var myLogs = await fakeLogCollector.GetLogsAsync(ct).Where(log => log.Category == "x").Take(3).ToListAsync();
Alternative designs
With optional start index
public class FakeLogCollector
{
/* ... existing code ... */
public IAsyncEnumerable<FakeLogRecord> GetLogsAsync(
int? startIndex = null, // ⬅️
CancellationToken cancellationToken = default
)
}
This API would allow for a more optimal solution when needing to start waiting from a previously known log state (assuming no Clear() is called). The caller would need to keep track of the previously awaited state, but would not need to perform re-iteration of log records that are not interesting.
With int count argument
public class FakeLogCollector
{
/* ... existing code ... */
public IAsyncEnumerable<FakeLogRecord> GetLogsAsync(
int? count = null, // ⬅️
CancellationToken cancellationToken = default
)
}
The iteration would stop when the number of returned logs reaches the count. However, this can be achieved by Skip(c) or custom iteration skipping as well. Also, the scenario of awaiting a fixed amount of log does not seem to be very useful here as opposed to MetricCollector where a minCount is awaited in order to retrieve a measurement snapshot.
Original proposal (archived)
Background and motivation
Sometimes you don't know the exact moment in testing when a log will be recorded, particularly if it's part of a background job or something similar, or for convenience you may use it to assert if something has finished before carrying out further assertions.
API Proposal
Basically this would be tacked on to the FakeLogCollector. The api is very similar to what the MetricCollector does. By default the timeout would be 5 seconds. I think typically the default would be to wait indefinitely, although if I'm writing a test I would find that annoying when a test hangs indefinitely if it fails. Maybe adding an option to set the default is another option.
Typically I'm waiting for certain logs in particular, so the most common thing for me would be to filter based on category.
public class FakeLogCollector
{
public ValueTask<FakeLogRecord?> WaitForLogAsync(CancellationToken cancellationToken);
public ValueTask<FakeLogRecord?> WaitForLogAsync(int millisecondsTimeout, CancellationToken cancellationToken);
public ValueTask<FakeLogRecord?> WaitForLogAsync(TimeSpan timeout, CancellationToken cancellationToken);
public ValueTask<FakeLogRecord?> WaitForLogAsync(int millisecondsTimeout);
public ValueTask<FakeLogRecord?> WaitForLogAsync(TimeSpan timeout);
public ValueTask<FakeLogRecord?> WaitForLogAsync(Func<FakeLogRecord, bool> filter, CancellationToken cancellationToken);
public ValueTask<FakeLogRecord?> WaitForLogAsync(Func<FakeLogRecord, bool> filter, int millisecondsTimeout, CancellationToken cancellationToken);
public ValueTask<FakeLogRecord?> WaitForLogAsync(Func<FakeLogRecord, bool> filter, TimeSpan timeout, CancellationToken cancellationToken);
public ValueTask<FakeLogRecord?> WaitForLogAsync(Func<FakeLogRecord, bool> filter, int millisecondsTimeout);
public ValueTask<FakeLogRecord?> WaitForLogAsync(Func<FakeLogRecord, bool> filter, TimeSpan timeout);
public ValueTask<IReadOnlyList<FakeLogRecord>> WaitForLogsAsync(Func<FakeLogRecord, bool> filter, int minCount, CancellationToken cancellationToken);
public ValueTask<IReadOnlyList<FakeLogRecord>> WaitForLogsAsync(Func<FakeLogRecord, bool> filter, int minCount, int millisecondsTimeout, CancellationToken cancellationToken);
public ValueTask<IReadOnlyList<FakeLogRecord>> WaitForLogsAsync(Func<FakeLogRecord, bool> filter, int minCount, TimeSpan timeout, CancellationToken cancellationToken);
public ValueTask<IReadOnlyList<FakeLogRecord>> WaitForLogsAsync(Func<FakeLogRecord, bool> filter, int minCount, int millisecondsTimeout);
public ValueTask<IReadOnlyList<FakeLogRecord>> WaitForLogsAsync(Func<FakeLogRecord, bool> filter, int minCount, TimeSpan timeout);
public ValueTask<IReadOnlyList<FakeLogRecord>> WaitForLogsAsync(int minCount, CancellationToken cancellationToken);
public ValueTask<IReadOnlyList<FakeLogRecord>> WaitForLogsAsync(int minCount, int millisecondsTimeout, CancellationToken cancellationToken);
public ValueTask<IReadOnlyList<FakeLogRecord>> WaitForLogsAsync(int minCount, TimeSpan timeout, CancellationToken cancellationToken);
public ValueTask<IReadOnlyList<FakeLogRecord>> WaitForLogsAsync(int minCount, int millisecondsTimeout);
public ValueTask<IReadOnlyList<FakeLogRecord>> WaitForLogsAsync(int minCount, TimeSpan timeout);
}
API Usage
An example waiting for a single log entry.
// At some point the fake log collector is made
var collector = new FakeLogCollector();
// imagine some logs are being written asynchronously
// if the log has already been recorded, returns immediately, otherwise will wait a matching log is found or until a certain amount of time is reached
var record = await collector.WaitForLogAsync(r => r.Category == "MyCategory");
// user can then do their own asserts on the results
Assert.That(record, Is.Not.Null);
Assert.That(record, Has.Message.EqualTo("my message"));
An example waiting for multiple log entry.
// At some point the fake log collector is made
var collector = new FakeLogCollector();
// imagine some logs are being written asynchronously
// if enough logs have already been recorded, returns immediately with logs matching the condition, otherwise will wait a certain number of matching log are found or until a certain amount of time is reached
var multipleRecords = await collector.WaitForLogsAsync(r => r.Category == "MyCategory", 2);
// user can then do their own asserts on the results
Assert.That(multipleRecords, Has.Count.EqualTo(2));
Assert.That(record[0], Has.Message.EqualTo("my message"));
Alternative Designs
As mentioned above MetricCollector already does this to some extent. It separates the waiting and the retrieval of the records. How this would work with the added filtering which isn't present in MetricCollector I'm not quite sure. I do find for convenience it's handy to do the filtering an retrieving all in one method.
Risks
It will likely indirectly impact parts of the underlying api that is already in use due to changes in how logs are collected so that they can be awaited on.
Hello @ItsVeryWindy, first of all, thank you for taking the time to write this proposal! I like the core idea of being able to await the logs for the reasons you mentioned. Regarding the API, let me propose an alternative and we can discuss here.
public Task WaitForLogAsync(
Func<FakeLogRecord, bool> endWaiting,
CancellationToken cancellationToken = default
)
public Task<bool> WaitForLogAsync(
Func<FakeLogRecord, bool> endWaiting,
TimeSpan? timeout,
CancellationToken cancellationToken = default
)
This alternative proposal aims at being leaner and more general purpose as returning the records using filter and minCount involves some ambiguity regarding what records exactly should be returned from the wait and assumes the caller is interested in these at all. Some points of the ambiguity: should past records be considered? when waiting for minCount=3, is the caller interested only in the third one or all three of them? Here instead, we only handle the point in time in which the next-to-come record has fulfilled the provided condition leaving the rest up to the caller.
@evgenyfedorov2 I'd love to see what you think!
I have PoCed this proposal in this PR draft, but let's keep the discussion here and focused on the API layer.
Thanks for giving it a look! 👍
I think to a degree there will always be a bit of ambiguity when testing asynchronous code. Lets assume for example I kick off an asynchronous job that has 3 calls to logs. which one would it return when waiting on it? If it's based on point in time it could the first, the second, or the third one.
If it's the third everything works out, you take a snapshot of the logs and count the number of records. But if it's one or two, that snapshot could contain at least 1-3 records. If it's less than 3, you'd have to wait again, but between you taking the snapshot the third could have already occurred so you end up waiting for nothing.
MetricCollector does consider past records when it waits. Considering past records does have it's downsides, sometimes I've waited for the same thing twice expecting the second call to return something different.
As another alternative or maybe in addition, you could also effectively stream the logs using something similar to the following, and leave the filtering up to the developer.
public IAsyncEnumerable<FakeLogRecords> WaitForLogs()
which would allow for code like collector.WaitForLogs().Where(r => r.Category == "x").Take(3).ToListAsync()
Hello @ItsVeryWindy, sorry for the radio silence, I've been off for some time.
I think the solution should enable the caller to fulfill the following two requirements without ambiguity: 1) await a point in time when a defined set of logs has been recorded. For example when 3 logs starting with some prefix exist in the snapshot. 2) Await another set of logs from that point onwards. For example a point in time when two more such logs were added.
You have a good point that my proposal lacks this ability, mainly because of the gap between checking the snapshot state and awaiting further logs. If there are altogether 3 logs expected of some kind and I want to await them, then starting awaiting when some are already logged never fulfills the condition and checking the snapshot before the awaiting creates the gap during which the sought log could be logged. I think the above-proposed streaming of logs suffers from the same issue as calling Take(3) when one is already recorded will never fulfill and checking the snapshot before creates the gap.
How about we provide the full snapshot in the waiting callback? This way, you could await state of the snapshot when 3 particular logs exist. You wouldn't need to check the snapshot first (thus avoiding the gap) and you would stop waiting successfully regardless of whether there was 0,1,2,3,+ logs of that kind already present when you started waiting (callback is first checked on the await start). To await further logs, you could mark the index from the previous wait and use it to design the condition for the subsequent logs.
Wdyt?
Hello @ItsVeryWindy, we like the proposal of being able to await logs and to write tests that are not flaky due to race conditions. Can you please check the latest proposal (original post edited) if you would find it useful in your scenarios? When we agree on the design, we may move forward to queue this for official API review.
cc: @evgenyfedorov2
I have marked this proposal as ready for API review, going forward with the latest design (see topmost comment) unless there are objections @ItsVeryWindy
- Decided the built-in skip or take were unnecessary, just use Skip or Take, as appropriate.
- Specify
[EnumeratorCancellation]if the implementation of this is based onyield return.
namespace Microsoft.Extensions.Logging.Testing;
public partial class FakeLogCollector
{
public IAsyncEnumerable<FakeLogRecord> GetLogsAsync(CancellationToken cancellationToken = default);
}
Adding my two cents because I've been implementing this kind of waiting over and over in multiple projects.
- await a point in time when a defined set of logs has been recorded. For example when 3 logs starting with some prefix exist in the snapshot. 2) Await another set of logs from that point onwards. For example a point in time when two more such logs were added.
This is what covers about 99% of my use cases so far (I implemented this in a separate logging provider, but it would fit into FakeLogCollector and I already have the code for a PR):
/// <summary>
/// Asynchronously waits until a log record matching the given predicate is created.
/// </summary>
/// <param name="predicate">The predicate that can match the log record.</param>
/// <param name="clear"><see langword="true" /> to atomically clear the set of accumulated log records up to and including the returned record; otherwise, <see langword="false" />.</param>
/// <param name="cancellationToken">A token that can be used to cancel the asynchronous operation.</param>
/// <returns>A <see cref="Task{FakeLogRecord}"/> that completes when a log record matching <paramref name="predicate"/> is created.</returns>
/// <exception cref="InvalidOperationException">
/// <paramref name="clear"/> is <see langword="true"/> and there are previously registered waiters
/// OR
/// There's already a pending waiter registered with <paramref name="clear"/> = <see langword="true"/>.</exception>
/// <remarks>
/// If <paramref name="predicate"/> matches an already existing log record, this method returns synchronously.
/// </remarks>
public Task<FakeLogRecord> WaitForLogRecordAsync(
Func<FakeLogRecord, bool> predicate,
bool clear = false,
CancellationToken cancellationToken = default)
BTW the two API proposals - getting an async stream via GetLogsAsync and waiting for a specific log record with WaitForLogRecordAsync are not mutually exclusive, both could be accepted and implemented.