Several fixes/tweaks to DDASLLogCapture. #512
Conversation
… bad token value was used to cancel. Also, should use asl_free instead of free, and should go before the return statement else that would be a leak when stopping. There is no need to avoid the log when a timestamp is not provided; just use the current time. Use "self" instead of a hardcoded class name; that can help if subclassing or copying code to a clone class, if needed for some reason (perhaps to add some DDLogMessage state based on certain log messages). Fixed "Received" misspelling. Lastly, creating ObjC objects when not necessary is extremely slow, and should be avoided if possible in a low-level framework like logging. It can be possible for log messages to be flooded and the log framework overhead should be kept minimal. In this case, several NSStrings were created just to parse numbers out of them, which can be done with C API functions.
| const char* secondsCString = asl_get( msg, ASL_KEY_TIME ); | ||
| const char* nanoCString = asl_get( msg, ASL_KEY_TIME_NSEC ); | ||
| NSTimeInterval seconds = secondsCString ? strtod(secondsCString, NULL) : [NSDate timeIntervalSinceReferenceDate] - NSTimeIntervalSince1970; | ||
| double nanoSeconds = nanoCString? strtod(nanoCString, NULL) : 0; | ||
| NSTimeInterval totalSeconds = seconds + (nanoSeconds / 1e9); | ||
|
|
There was a problem hiding this comment.
One thing which I did in my custom version of this was to use "asl_log" as the function name instead of nil -- our formatter does not use filenames in the output, but does use function names, so that gives a hint as to where it came from. I could add that here if that is desirable.
|
👍 |
|
Looks great except for the Travis maybe unrelated error here. |
|
Considering those tests don't invoke DDASLLogCapture at all, those would be unrelated. Really, I don't think those tests are safe to be async. You see logs from previous tests getting intermingled with that last test which failed. It looks one test could still be executing, then a new test instance can be created which calls DDLog removeAllLoggers and installs a new one, and if the background thread for the previous async DDLogDebug() etc. had not started yet, the new test's logger will be the one to get the logs. You would probably be better off making them all synchronous and using DDLog flush as the first thing in -setUp, and then again at the end of the test. |
|
I run Travis in master to be sure, and it passed. Which is weird. The thing is if we break Travis we can't safely merge subsequent pull requests. |
|
I don't think it's weird... the tests themselves need to be fixed. As I see it right now, it depends on thread execution order. The global list of loggers is not something you can easily use with async tests -- they can conflict with each other. If one test routine ends, and the next one happens to begin (and call -setUp) before the DDLogDebug() call has fully filtered down to the loggers (which involves two separate background queues), then the logger from the previous async test gets removed before the logs get to it, and get passed to the next test's logger instead. I think there are other pull requests with spurious failures too, for the same reason -- nothing to do with the PRs. So yes, there probably needs to be a commit which fixes the tests first. |
|
I still think this is weird. Why this commit would change the execution order this way? |
|
It wouldn't. This code is not invoked during the unit tests at all, so it cannot have any effect. While the tests at first blush look OK, in the errors in Travis above, it's pretty clear that logs sent from one unit test were not delivered to loggers until another unit test's logger had been put in instead. It sure looks like some tests are being run in parallel, or at least the -setUp method on one of them is getting called while another test is still going. It feels like a race condition, which will often but not always work. #497 and #499 also seem to have unrelated Travis failures for similar reasons. |
|
OK, I think I see what is happening. testLoggerLogLevelAsync puts in a logger which only handles Errors and Warnings, then fires off five logs (expecting that only two get through). However, the expectations are set up that they are fulfilled once the expected number of logs come across, and the logs in that test are ordered Error-Warning-Info-Debug-Verbose. Thus, it is entirely possible that the Error and Warning logs get handled and sent to the logger, which then fulfills its expectation, with the three subsequent logs still waiting to be processed by the queues. Since the expectation is filled, the test ends, and the testX_ddLogLevel_async starts which removes the old logger and puts in its own, which is only expecting Error-Warning-Info logs. Nothing calls DDLog flush first to clear out the existing ones, so then the Debug and/or Verbose logs from the previous test get sent to the new logger and cause errors. At the very least, I would put a call to [DDLog flush] right after [DDLog removeAllLoggers] but before adding a new logger in the -setUp code. That should clear out any pending log messages to avoid them polluting the new test. Second, some of those tests really aren't checking to see if unexpected logs get delivered -- they are ending as soon as they see the expected ones. You could either change the order of the logs in those case (put the unexpected-to-see ones first, so they will cause errors), and it probably would also be a good idea to call [DDLog flush] in the test cases themselves (after the expectation) then validate the number of logs actually delivered to the logger. I don't think it's doable with the expectation fulfill logic alone, since it would have no idea if invalid logs were still in flight or not. I don't think the use of expectations is really required -- you could probably just replace those with [DDLog flush]. |
|
The race condition making some tests fail occurred on master after @rivera-ernesto merged #514. https://travis-ci.org/CocoaLumberjack/CocoaLumberjack/builds/63171538 |
|
The second thing is that I'm not sure that the local ddLogLevel global variable in the unit test is being used at all. That should have prevented the final Debug/Verbose logs from ever getting to the TTYLogger, but it sure looks like those are still there. Looking at DDLogMacros.h, either LOG_LEVEL_DEF or ddLogLevel needs to be explicitly #defined otherwise the macros use a hardcoded DDLogLevelVerbose. I do not see that the unit tests #define anything before importing CocoaLumberjack.h. CocoaLumberjack 1.x would just assume that the ddLogLevel variable was global and available, but no longer. You would have to do something like #define ddLogLevel ddLogLevel or something before importing the header, I think, to make the current unit test actually work. However, given the ordering of the logs, the last test would usually complete with a pass before the unexpected logs are actually delivered. The test might complete though, and deallocing the mocks probably removes the stubbed methods on the original object, so even if the logger is left in the global logger list by the last test, it is an empty DDAbstractLogger instance which normally does nothing. I suspect more issues will happen on OSX, since on multiprocessor machines the delivery to the individual loggers all happen on concurrent individual threads, while on single processor it is all synchronous on the central logger queue's background thread, with the loggers invoked serially. |
Which is again weird because both master and #514's Travis builds were succeeding. Let's merge this and then fix the unit tests. |
Several fixes/tweaks to DDASLLogCapture.
Several tweaks to DDASLLogCapture.
First, -stop was not working, because a bad token value was used to cancel. Either the notifyToken value should be declared __block, or the token parameter in the block argument should be used (I did the latter). Currently, the initial value of 0 is just captured by the block, and is using that to cancel, which doesn't work.
Should use asl_free instead of free I believe, and it should go before the cancel return statement else that would be a leak when stopping.
I don't think there is a need to avoid the log when a timestamp is not provided; so I changed to just use the current time in that situation.
Use "self" instead of a hardcoded class name; that can help if subclassing or copying code to a clone class, if needed for some reason (perhaps to add some DDLogMessage state based on certain log messages, to aid custom formatters).
Fixed "Received" misspelling.
Lastly, creating ObjC objects when not necessary is extremely slow, and should be avoided if possible in a low-level framework like logging. It is possible for log messages to be flooded and the log framework overhead should be kept minimal. In this case, several NSStrings were created just to parse numbers out of them, which can be done with C API functions.