Skip to content
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.

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

Add a testing log handler proposal #316

Open
wants to merge 3 commits into
base: main
Choose a base branch
from
Open
Changes from 1 commit
Commits
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
112 changes: 112 additions & 0 deletions proposals/0002-testing-log-handler.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,112 @@
# Test Log Handler

Authors: [Brian Maher](https://github.com/brimworks), [Konrad 'ktoso' Malawski](https://github.com/ktoso)

## Introduction

Software operators rely on logging to provide insight into what is being done,
therefore, testing log output is an important facet.

## Motivation

A variety of implementations have cropped up organically, but having a single
test log handler to build off of will reduce the re-write churn.

### Existing Implementations

* [swift-log-testing](https://github.com/neallester/swift-log-testing)
* [swift-distributed-actors/LogCapture](https://github.com/apple/swift-distributed-actors/blob/main/Sources/DistributedActorsTestKit/LogCapture.swift)
* [swift-cluster-membership/LogCapture](https://github.com/apple/swift-cluster-membership/blob/main/Tests/SWIMTestKit/LogCapture.swift)
* [RediStack/RedisLoggingTests](https://github.com/swift-server/RediStack/blob/master/Tests/RediStackIntegrationTests/RedisLoggingTests.swift)
* [swift-log/TestLogger](https://github.com/apple/swift-log/blob/main/Tests/LoggingTests/TestLogger.swift#L52)


## Features

A testing log handler needs the following features:
* The ability to capture log entries at the start of a unit test.
* The ability to assert the captured log entries contain a matching message.
* Work correctly in the face of parallel test execution.
* Print log messages to the console if the log entry does not match a log entry
that is being asserted.
* Bootstrap the test log handler as early as possible so we don't miss any
`Logger()` creations which may happen during setup.

## Proposed Solution

A global function to bootstrap the test log handler:

```swift
TestingLogHandler.bootstrap()
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why don't we call the regular bootstrap method here? Furthermore, I think when we do this we should also make the init of Logger finally public that just takes a LogHandler so APIs that accept Loggers can be tested by just creating a TestingLogHandler, creating a logger with it and then calling the API with that logger.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why don't we call the regular bootstrap method here?

As I recall, the LoggingSystem.bootstrap() must be called exactly once, so my thought was to encapsulate the logic for ensuring it is initialized exactly once into the LoggingSystem.bootstrap() method, but perhaps I am mistaken in my understanding?

Furthermore, I think when we do this we should also make the init of Logger finally public that just takes a LogHandler so APIs that accept Loggers can be tested by just creating a TestingLogHandler, creating a logger with it and then calling the API with that logger.

I'm not opposed to that change, however I have found that it isn't to uncommon to find code which does not expose a way to "inject" the Logger instance (or trying to "inject" it with our custom log handler is rather onerous).

Overall, I do like the idea of making the Logger constructor that takes a LogHandler instance as public, but I'd like to also have a way to capture logs too.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Honestly, I feel this situation needs to be resolved in a separate proposal where the bootstrap method is relaxed, perhaps only in debug mode.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

BTW, @FranzBusch when putting together the sample implementation I noticed that there already is Logger() constructors (aka init()) that allow one to specify a log factory, so it looks like this comment is already done:

Furthermore, I think when we do this we should also make the init of Logger finally public that just takes a LogHandler so APIs that accept Loggers can be tested by just creating a TestingLogHandler, creating a logger with it and then calling the API with that logger.

@Mordil said:

Honestly, I feel this situation needs to be resolved in a separate proposal where the bootstrap method is relaxed, perhaps only in debug mode.

Perhaps... but I do think that if we have a reasonably good test logger which allows one to do initialization exactly once, then there is no need to allow for multiple initialization.

Actually, one way to get around the multiple initialization problem is to specify a log factory that delegates to an implementation which can be changed... actually, maybe I should use that idea in the current log tests since I'm trying to allow the current tests to be minimally modified (which means supporting multiple log handlers).

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Actually, one way to get around the multiple initialization problem is to specify a log factory that delegates to an implementation which can be changed... actually, maybe I should use that idea in the current log tests since I'm trying to allow the current tests to be minimally modified (which means supporting multiple log handlers).

So, I went ahead and made an attempt at writing a log factory delegate here:

https://github.com/brimworks/swift-log/blob/testing-log-handler-proposal-delegated/Sources/Logging/DelegatedLogHandler.swift

Unfortunately, the current log unit tests rely on the copy on write behavior of structs, but my DelegatedLogHandler needs to be a class so we can keep track of any outstanding LogHandlers and update them (using a weak map). If I can find a way to replicate the copy on write behavior of structs in a class then I think I could get this to pass the current tests.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am still not convinced this is the right thing to do in tests here. IMO if developers want to test their logs I don't think they should use bootstrapping of a test log handler but rather they should accept a Logger and we can create a Logger(handler: TestLogerHandler(). This would make this proposal a lot simpler since we don't need containers anymore.

Furthermore, it would push developers into the right pattern which is to accept a Logger at their APIs and potentially fallback to create a Logger if none is passed.

```

A way to create a new "container" which will capture all log messages that match
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am not sure I follow the container principle yet. Should the testing log handler start by capturing all logs and metadata and then provide easy assertion APIs in the end? Potentially a connection to swift-testing that makes that as easy as possible would be great.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should the testing log handler start by capturing all logs and metadata and then provide easy assertion APIs in the end?

The "container" is a "recorder" that allows one to specify a pre-filter such that only log messages which match the pre-filter are placed in the "container". If you want to have a "dumb" recorder, simply specify a pre-filter that always returns true. However, if you blindly record all log messages, then nothing will be printed to the console since everything will be matched by your container, and in the design I propose only non-matching log messages will be printed to the console.

In my experience, having log messages "swallowed" by the recorder (aka container) may cause hours more debugging since important log messages (like exceptions getting logged) are not printed to the console in that scenario.

Would you prefer if I rename the "container" to "recorder"? Or is there another concern I'm missing?

Potentially a connection to swift-testing that makes that as easy as possible would be great.

Do you have ideas on this? Right now, I'm suggesting that users of the API simply assert the container has at least one matching log message, which is pretty trivially asserted in all unit test frameworks... and since non-matching logs are printed to the console, it should be pretty easy to observe if a log message that you expected to match didn't match by looking at the other log message(s) printed to the console.

Copy link
Member

@ktoso ktoso Aug 22, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I propose only non-matching log messages will be printed to the console.

I don't think this is right, at least not by default; A "log capture" log handler should capture all logs, then we assert on those (or filter out and are able to eagerly drop some), but we should not cause prints to happen.

If an assertion fails, there should be a way to "there was an error (the error); dump all the logs captured". This is how I use logging of vast quantities of logs, and I get the "important" logs dumped when an assertion has failed.

But I don't think "passed" execution should be logging anything by default; in fact, tests which print much output are an anti pattern imho and stdout should be empty if nothing went wrong

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think this is right, at least not by default; A "log capture" log handler should capture all logs, then we assert on those (or filter out and are able to eagerly drop some), but we should not cause prints to happen.

Let me tell you a story about when our team first attempted to add log assertions to our code base. Initially we added a dependency on neallester/swift-log-testing and we followed the example:

override func setUp() {
        TestLogMessages.bootstrap() 
}

We added in our log assertions and everything was great... until our CI pipeline broke and we realized that none of our log messages got printed, and since the logs were existing with signal 11 we had no idea what the problem was. In fact, this different design (print non-captured log messages) was partially motivated by this inoculating experience.

Therefore, I highly recommend that whatever final approach we land on will continue to default to printing logs at least when running tests that are not trying to use the log testing framework.

If an assertion fails, there should be a way to "there was an error (the error); dump all the logs captured". This is how I use logging of vast quantities of logs, and I get the "important" logs dumped when an assertion has failed.

What if the code which performs the log assertion is never executed? I can think of many scenarios where I have experienced this: exception is thrown, process segfaults, etc.

But I don't think "passed" execution should be logging anything by default

In the current design, if a log matches any container, then the message is not logged. Maybe I didn't make that part clear?

in fact, tests which print much output are an anti pattern imho and stdout should be empty if nothing went wrong

Agreed... and if you use the test logging framework I propose, then any log message that matches an "expectation" won't be printed.

What do you think of this idea? Instead of having a container with a pre-filter as I currently have designed, what if I borrow some ideas from java EasyMock. More specifically, what if you could define a set of "expectations" for log messages, and then at the end of your test you can "verify" these expectations.

So, a typical usage might look like this:

class TestMyLogs: XCTestCase {
    override func setUp() {
        TestingLogHandler.bootstrap() 
    }
    func testExample() {
        // Logger may be created before the verifier:
        let logger = Logger(label: "Example")
        let verifier = LogVerifier()
        verifier.expect(label: "Example", level: .debug, message: Regex("^Message$"))
        logger.debug("Message")
        // Performs assertion(s) on all expectations. If any expectation fails, the expectation(s)
        // that fail are printed in the assertion failure. This call also resets all expectations.
        verifier.verify()
        // This call would fail, with an error indicating that there are no expectations set.
        verifier.verify()
    }
}

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Couldn't this behavior be a flag passed, so that people who need to debug/inspect their test executions more deeply can - and for those who don't, have their ideal clean stdout?

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Couldn't this behavior be a flag passed, so that people who need to debug/inspect their test executions more deeply can - and for those who don't, have their ideal clean stdout?

In the current implementation I have proposed, just collect all the logs by specifying a pre-filter that selects all logs { true } and then you can get a "clean" stdout during that test run, and you can iterate over the container of logs collected to do all the normal assertion stuff you might want to do. I don't advocate for using it in that way, since I find it more useful to be selective up-front using a pre-filter, but the current implementation I have suggested supports both uses.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Similar to my comment above. I am not convinced we need this complicated container API if we should expect users to properly accept Loggers at the API level. We can then just store all log messages in the test log handler and assert on that. This should also work during parallel test execution

a filter. Note that multiple concurrent "container"s need to collect duplicate
log messages, since tests may be ran in parallel.

To create a new "container" we can have a function that takes a filter parameter
and returns the new log container:

```swift
let container = TestingLogHandler.container { logMessage in
// Ideally, you would be as specific as possible in your filtering!
return logMessage.level == Logger.Level.debug &&
logMessage.label == "Test" &&
logMessage.message.description == "Matched"
}
// Emit a log that matches the filter:
Logger(label: "Test").debug("Matched")

// Emit a log that does NOT match the filter:
Logger(label: "Test").debug("Printed to console")

// Assert that the log message was found:
XCTAssertFalse(container.messages.isEmpty)
```

It is recommended to create a separate container for each log assertion so that
you can simply check that the messages in a container are non-empty. If you use
this pattern you also protect yourself from accidental log message matches that
occur due to a test ran in parallel. An accidental match could cause a failing
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

How so? The testing log handler is global, we may get multiple containers but it concurrently logging from various tests/threads, won't they end up in all currently active containers?

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The testing log handler is global, we may get multiple containers but it concurrently logging from various tests/threads, won't they end up in all currently active containers?

Yes that is correct understanding. Maybe I need to elaborate a bit more here... but the scenario that I'm thinking of is where test A causes log message X to be printed and test B also causes log message X to be printed. If test A and B are ran such that the log containers for test A and B are both created before log message X is printed, and the log message X is printed before test A and B assert the container is non-empty, there could be multiple messages in the container. Therefore asserting that there is exactly one message could lead to spurious errors.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think I'm more in favor of giving more powerful assertion capabilities that solve the filtering, rather than having a robust filtering API, because the former is less work for the library to build, test, and maintain, than the filtering capabilities of the log handler.

It's also more familiar territory for those looking for test utilities, as it's a bit more discoverable due to the fact you're reaching for these tools as you're drafting your assertions rather than when you're in the mindset of bootstrapping the test (at least to me)

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the feeback @Mordil!

because the former (more powerful assertion capabilities) is less work for the library to build, test, and maintain, than the filtering capabilities of the log handler.

Really? I would think it would be the opposite. More specifically, any assertion capability needs to have the exact same logic as the filtering capabilities... since an assertion is really just a fancy "filter" that not only returns true/false built in the event of failure it would print a nice debug message to assist.

It's also more familiar territory for those looking for test utilities, as it's a bit more discoverable due to the fact you're reaching for these tools as you're drafting your assertions rather than when you're in the mindset of bootstrapping the test (at least to me)

Maybe the real problem is with the names I have chosen. Instead of having a "container" that has a pre-filter as I have done so far. What if we reduce the capabilities and instead have the exact same API but call this a "future log assertion"... and then later in the test you simply assert that this "future log assertion" got called (and remove the capability of introspecting any log messages that got captured). This would be similar to many "mock" frameworks which allow one to validate that certain methods on the "mock" got called. Do you think that would be more intuitive and discoverable?

Copy link

@Mordil Mordil Aug 22, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Obviously, I'll use whatever is settled on, and I think there's merit to both approaches.

My main feedback is just try to find the solution that requires the least amount of effort, has the least room for bugs, and perhaps has the most extensibility outside of the module so this library doesn't need to see frequent bug/feature requests on this aspect.


I guess it's one of those "I'll know it if I see it" scenarios for me.

When I see the up-front filtering, I'm jumping (and this is where I may be wrong 😅) to the idea of an implementation that needs to track all of that, with a "nice" API for describing the filtering.

Vs. the assertions route is much more language primitives where we just store them, and then APIs for exposing those data structures and then relying on built-in methods like filter, map, etc.

In the former, I'd think you'd need more internal data structures, more internal logic. While in the latter, I'm thinking it's more of just a plain data structure of arrays.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@Mordil are you willing to put a little effort in and try out the implementation I have proposed? If you want to, you can have the pre-filter match all logs. When that container is active, no longs will be printed to stderr.

class TestMyLogs: XCTestCase {
    override func setUp() {
        TestingLogHandler.bootstrap() 
    }
    func testExample() {
        // Logger may be created before the container:
        let logger = Logger(label: "Example")
        let container = TestingLogHandler.container { true }
        logger.debug("Message")
        XCTAssertTrue(container.messages.find { $0.match(label: "Example", level: .debug) }, "Expected log message with label: Example, level: debug, but got \(container.messages.map { "\($0)" }.joined("\n"))")
    }
}

...and you could aways add extensions to the TestingLogHandler.Container if you want to make it easier to write assertions like the one above.

So, I think what I currently propose is the minimal code with maximal flexibility.

Personally, I wouldn't use it in this way, but everyone has their own preferences :).

test to spuriously succeed, but it would never cause a successful test to
spuriously fail.

If a log message is emitted that does **not** match any container's filter, it
will be printed to the console in the same way as the default built-in log
handler.

In order to make filtering easier, the `LogMessage` struct contains a `match`
function that takes the following optional parameters:
* label: `String?`
* level: `Logger.Level?`
* message: `Regex<AnyRegexOutput>?`
* metadata: `[(Logger.Metadata.Element) -> Bool]`
* source: `Regex<AnyRegexOutput>?`
* file: `Regex<AnyRegexOutput>?`
* function: `String?`
* line: `UInt?`

Only if all specified parameters match will this function return true.

In order to make debugging easier, the `LogMessage` struct will implement
`CustomStringConvertible` which causes the log message to be formatted in the
default built-in log handler format.

Additionally, each field of the log message is public and can be used for
custom filtering:
* timestamp: `Date`
* label: `String`
* level: `Logger.Level`
* message: `Logger.Message` (note that this is also `CustomStringConvertible`)
* metadata: `Logger.Metadata`
* source: `String`
* file: `String`
* function: `String`
* line: `UInt`

Note that the log handler implementation must maintain "weak" pointers to all
the containers so as to avoid memory leaks.

Also note that the `LogHandler.logLevel` is **always** `.trace`, otherwise log
messages that are at to low of a level will not have a chance to be captured
due to the `if self.logLevel <= level` guard on the `Logging.log()` method.