Add a testing log handler proposal

[brimworks]

Proposal for implementing a testing log handler which is provided by swift-log. For additional context, please see this github issue: #242

[ktoso]

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?

[brimworks]

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.

[Mordil]

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)

[brimworks]

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?

[Mordil]

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.

[brimworks]

@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 :).

[ktoso]

Overall looks good to me, I think we could prepare a PR with the APIs / implementation. This has come up frequently and has been implemented independently in at least 3-4 projects I know of. We can fine tune the behavior once a PR with impl is present :)

[FranzBusch]

Thanks for working on this! I agree that we should have a way for testing logging in this package. I am not yet sure I agree with the container principle outlined here instead of just having a "recorder" testing log handler that makes it easy to assert on what it recorded.

[FranzBusch]

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.

[brimworks]

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.

[Mordil]

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

[brimworks]

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).

[brimworks]

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.

[FranzBusch]

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.

[FranzBusch]

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.

[brimworks]

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.

[ktoso]

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

[brimworks]

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()
    }
}

[Mordil]

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?

[brimworks]

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.

[FranzBusch]

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

[brimworks]

So, I started putting together an example implementation, and in the process I'm refactoring the existing swift-log tests so they don't use LoggingSystem.bootstrapInternal() since multiple calls to LoggingSystem.boostrap() triggers the "Logging.swift:617: Precondition failed: logging system can only be initialized once per process." error.

...and low and behold, the LoggingTest testMultiplex test is failing due to the fact that some extra medatadata (["example": example-value]) is getting injected as a side-effect of another concurrently executing test.

So, whatever solution we come up with needs to be a bit less fragile in the face of concurrent test execution than the current solution. Note that I intend to do minimal changes to the current test solution so we can be assured that a bug in our test logger doesn't get hidden. Additionally, it will allow us to iterate on the test logger implementation provided by this proposal without impacting the other unit tests. Longer term we can see about removing that redundancy, but I'd rather do that as a separate PR.

I'll update this PR with my proposal soon.

[brimworks]

PR has been updated with a proposed implementation. I also refactored the tests so they rely on bootstrapInternal() a bit less, although I couldn't completely remove the usage of this since some of the tests are testing the interactions at a "global" level.

Overall, I'd suggest that we minimize the usage of bootstrapInternal() though.

[Mordil]

I don't see anything wrong with this direction from my perspective

[FranzBusch]

Thanks so much for working on this! Overall, I am still in support of providing test facilities to make it easy to assert certain log messages were emitted; however, I am currently -1 on this proposal for two reasons:

1. I don't think we should have a global test logging system bootstrap but rather we should push developers who want to test their logs to accept Loggers on their API.
2. If we do 1. then I feel like the concept of containers isn't needed anymore

@brimworks Assuming that APIs accept a Logger do you still think there is a reason to retain the test logging bootstrap method?

[FranzBusch]

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.

[FranzBusch]

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

[FranzBusch]

This should be available on all platforms we support

[brimworks]

This was needed to support Regex

[FranzBusch]

I am not sure if we need this method at all. Why can't users just write

#expected(capturedLogMessage.message == "foo")

[brimworks]

Typically you would be working with multiple log messages rather than a single captured one.

Perhaps the real desire here is to provide a better error message in the event that no single log message matches? For example, if you setup a container so that it only has log entries that match message == "foo", then if no log messages matches, printing an error to the effect of no log entry matches message == "foo" would be desirable. Let me see if I can come up with a design for that.

[brimworks]

I've updated the design proposal so that a new "assertion" method (under the covers it would really just wrap a log "container"). Let me know if you like that idea and I can add that wrapper.

[FranzBusch]

Can we just use a LockedValueBox containing an array of messages?

[brimworks]

Like this LockedValueBox? https://github.com/apple/swift-distributed-tracing/blob/1.1.1/Sources/Instrumentation/Locks.swift#L129

I figured that swift-log would have a no dependencies policy, in case the swift distributed tracing code wants to use swift-log, but maybe I misunderstand your suggestion?

[brimworks]

... maybe you mean this RWLockedValueBox which is not public (defined in Logging.swift)? If I move this code into a separate target, I don't think I will have access to that code, right? Did you want to make the code public?

[brimworks]

@FranzBusch I have been thinking over your comment over the course of the last week:

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.

Although I agree with your sentiment (everyone should allow a Logger to be "injected" into their public APIs), I don't think this is a realistic requirement that we should be hoisting on anyone that wants to add some rigor to their logs by testing that the desired log output is achieved.

Therefore, I would rather "embrace the genius of the and" and encourage users of the library to inject in their log handler manually, but still allow bootstrapping to a singular test log handler instance.

So, the way I take your feedback is that we need an easy way to inject the test log handler without requiring a bootstrap. Let me see if I can come up with a good solution to this problem.

[brimworks]

@brimworks said:
So, the way I take your feedback is that we need an easy way to inject the test log handler without requiring a bootstrap. Let me see if I can come up with a good solution to this problem.

BTW, I changed the test case to use the "easily inject a TestLogHandler instance" way which avoids bootstrapping. Let me know if this addresses your concern.

Thanks!