Add a testing log handler proposal #316
Conversation
| 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 |
There was a problem hiding this comment.
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?
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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)
There was a problem hiding this comment.
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?
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
@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 :).
There was a problem hiding this comment.
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.
| A global function to bootstrap the test log handler: | ||
|
|
||
| ```swift | ||
| TestingLogHandler.bootstrap() |
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
Honestly, I feel this situation needs to be resolved in a separate proposal where the bootstrap method is relaxed, perhaps only in debug mode.
There was a problem hiding this comment.
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).
There was a problem hiding this comment.
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:
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.
There was a problem hiding this comment.
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.
| TestingLogHandler.bootstrap() | ||
| ``` | ||
|
|
||
| A way to create a new "container" which will capture all log messages that match |
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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
There was a problem hiding this comment.
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()
}
}There was a problem hiding this comment.
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?
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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
|
So, I started putting together an example implementation, and in the process I'm refactoring the existing ...and low and behold, the 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. |
|
PR has been updated with a proposed implementation. I also refactored the tests so they rely on Overall, I'd suggest that we minimize the usage of |
There was a problem hiding this comment.
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:
- 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. - 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?
| A global function to bootstrap the test log handler: | ||
|
|
||
| ```swift | ||
| TestingLogHandler.bootstrap() |
There was a problem hiding this comment.
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.
| TestingLogHandler.bootstrap() | ||
| ``` | ||
|
|
||
| A way to create a new "container" which will capture all log messages that match |
There was a problem hiding this comment.
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
| } | ||
|
|
||
| // Easily check if log message matches certain characteristics: | ||
| @available(macOS 13.0, *) |
There was a problem hiding this comment.
This should be available on all platforms we support
There was a problem hiding this comment.
This was needed to support Regex
|
|
||
| // Easily check if log message matches certain characteristics: | ||
| @available(macOS 13.0, *) | ||
| public func match( |
There was a problem hiding this comment.
I am not sure if we need this method at all. Why can't users just write
#expected(capturedLogMessage.message == "foo")
There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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.
| // Guarded by queue: | ||
| private var _messages: [LogMessage] = [] | ||
|
|
||
| private let queue: DispatchQueue |
There was a problem hiding this comment.
Can we just use a LockedValueBox containing an array of messages?
There was a problem hiding this comment.
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?
There was a problem hiding this comment.
... 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?
|
@FranzBusch I have been thinking over your comment over the course of the last week:
Although I agree with your sentiment (everyone should allow a 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. |
* Factor out TestLogHandler into a new LoggingTestKit target & library * Add proper copywrite to TestLogHandler * Rename TestingLogHandler to TestLogHandler * Rename LogMessage to CapturedLogMessage * Add a TestLogHandler.Container.factory property to allow for the creation of Logger(label: ..., factory: ...) instances which are bound to this specific container rather than any arbitrary container. * Remove bootstrapInternal() since we can't use `LoggingSystem.bootstrapInternal()` due to the refactor. * Remove the requirement for initialization from `TestLogHandler.container()` method so we can support manual "injection" of the log handler. * Modify the TestTestingLogHandler.swift test so it uses this new manual "injection" method. * Update the proposal design doc.
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! |
|
For anyone else following along, the fate of this proposal is in limbo due to an open question about how to pass loggers around (should we be using task locals?). Based on the outcome of that decision, we may want to take a different tactic for testing (aka use task local logger handlers). |
That's right but I think we could scope this down and still make progress with the PR. In my opinion, just creating one log handler that is recording all logged messages and allows us to easily assert what is recorded is valuable regardless of how we move forward with the logger passing. I would recommend that we focus on that for now to make this PR easier to move forward. |
There was a problem hiding this comment.
Thanks for working on this! I left some code comments inline. My biggest meta level feedback at this point is if we need the concept of containers at all. I already see great value by landing a log handler that just records all messages to get started with and then build it out from there.
| // | ||
| //===----------------------------------------------------------------------===// | ||
|
|
||
| import Foundation |
There was a problem hiding this comment.
Can we avoid the Foundation import here. We normally try to stay clear of foundation in those lower level packages. We can do the data formatting without foundation as well.
| import Darwin.C | ||
| #endif | ||
|
|
||
| public struct CapturedLogMessage: CustomStringConvertible { |
There was a problem hiding this comment.
I would suggest a slightly different name
| public struct CapturedLogMessage: CustomStringConvertible { | |
| public struct RecordedLogMessage: CustomStringConvertible { |
We also need to make this type Sendable. Should we make it Equatable and Hashable as well?
| public var timestamp: Date | ||
| public var label: String | ||
|
|
||
| public var level: Logger.Level | ||
| public var message: Logger.Message | ||
| public var metadata: Logger.Metadata | ||
| public var source: String | ||
|
|
||
| public var file: String | ||
| public var function: String | ||
| public var line: UInt |
There was a problem hiding this comment.
Can we add some doc comments to all of those public properties
| public var function: String | ||
| public var line: UInt | ||
|
|
||
| public var prettyMetadata: String { |
There was a problem hiding this comment.
Do we need to expose this publicly?
| } | ||
|
|
||
| public var description: String { | ||
| "\(Self.timestampFormat.string(from: timestamp)) \(level) \(label) :\(prettyMetadata) [\(source)] \(message)" |
There was a problem hiding this comment.
We should probably format the timestamp once in the init to make this a bit more performant even if it is only in test code.
| } | ||
|
|
||
| public struct TestLogHandler: LogHandler, Sendable { | ||
| public typealias Filter = (CapturedLogMessage) -> Bool |
There was a problem hiding this comment.
We normally try to avoid typealiasis since they are often surfaced badly in tooling. Can we just avoid this?
| public struct TestLogHandler: LogHandler, Sendable { | ||
| public typealias Filter = (CapturedLogMessage) -> Bool | ||
|
|
||
| public final class Container: @unchecked Sendable { |
There was a problem hiding this comment.
I am not yet convinced that we need this type or concept. The thing that I am most worried about is that the container is a reference type. I can understand that after a test you would want to filter all the logged messages by a predicate and then assert on top of the filtered messages but this type is live-updated.
How strongly do you think that this type is needed?
| } | ||
| } | ||
|
|
||
| private static let queue = DispatchQueue(label: "TestLogHandler") |
There was a problem hiding this comment.
Can we instead use a lock to protect this state here? I don't recall of this project contains a locked value box but that or the Mutex from the stdlib would be preferable
| // Guarded by queue: | ||
| private static var _containers: [Weak<Container>] = [] | ||
|
|
||
| public static func bootstrap() { |
There was a problem hiding this comment.
I am leaning towards not offering this method and rather let the user in their tests do this. If they already have code that accepts a logger we just need to make the init public and they should be able to avoid bootstrapping completely.
| } | ||
|
|
||
| // Override the default global log level (defaults to .info) | ||
| public static func setLevel(_ level: Logger.Level) { |
There was a problem hiding this comment.
Instead of a method can we expose the property publicly instead
Proposal for implementing a testing log handler which is provided by swift-log. For additional context, please see this github issue: #242