-
Notifications
You must be signed in to change notification settings - Fork 302
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
base: main
Are you sure you want to change the base?
Changes from 1 commit
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
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() | ||
``` | ||
|
||
A way to create a new "container" which will capture all log messages that match | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. I am not sure I follow the There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
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 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?
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. Choose a reason for hiding this commentThe 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. 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. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
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.
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.
In the current design, if a log matches any container, then the message is not logged. Maybe I didn't make that part clear?
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. Choose a reason for hiding this commentThe 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? There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
In the current implementation I have proposed, just collect all the logs by specifying a pre-filter that selects all logs There was a problem hiding this comment. Choose a reason for hiding this commentThe 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 |
||
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 | ||
There was a problem hiding this comment. Choose a reason for hiding this commentThe 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? There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
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. Choose a reason for hiding this commentThe 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) There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Thanks for the feeback @Mordil!
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.
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. Choose a reason for hiding this commentThe 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. There was a problem hiding this comment. Choose a reason for hiding this commentThe 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 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. |
There was a problem hiding this comment.
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 aLogHandler
so APIs that acceptLogger
s can be tested by just creating aTestingLogHandler
, creating a logger with it and then calling the API with that logger.There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
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 theLoggingSystem.bootstrap()
method, but perhaps I am mistaken in my understanding?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 aLogHandler
instance as public, but I'd like to also have a way to capture logs too.There was a problem hiding this comment.
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.
There was a problem hiding this comment.
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 (akainit()
) that allow one to specify a log factory, so it looks like this comment is already done:@Mordil said:
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.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
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 outstandingLogHandler
s 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.
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 aLogger(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 aLogger
if none is passed.