We've been using our own logging system for quite a long time but we are interested in the benefits offered by Logger/OSLog and plan to migrate to it.
Before modifying thousands of logging calls, we want to understand a bit more how, when and where (ie. from which thread/queue) OSLog strings interpolation is performed.
More specifically, we are concerned by simultaneous access to properties from different threads. Our app usually handles that using DispatchQueues (single or concurrent) and calls to our logging system is safe as the log string is built synchronously.
On the other hand, when using Logger/OSLog, the provided string is in fact an OSLogMessage which keeps a reference to values and properties in order to build the final String later (asynchronously). If it is correct, the "later" part concerns us.
Example
Let's consider the following class property profile (instance of Profile class which implements CustomStringConvertible):
private var profile: Profile?
With our own logging system, we used to log the profile property at the time the logging method is called (and when the access to profile is safe):
Log.debug(logModule, "Current profile: \(profile)")
Now moving to Logger/OSLog, the following error appears:
logger.debug("Current profile: \(profile)")
// Reference to property 'profile' in closure requires explicit use of 'self' to make capture semantics explicit
Our understanding is that the property profile is not accessed synchronously but later, possibly after or even worse while the property is being mutated from another thread (-> crash). In which case fixing the error using "Current profile: \(self.profile)" instead would be a very bad idea...
The same goes with class instance properties used in the implementation of CustomStringConvertible.description property. If the description property is built asynchronously, the class instance properties may have been mutated or may be being mutated from another thread.
TL;DR
We have searched for good practices when using Logger/OSLog but could not find any dealing with the thread-safeness of logged objects.
- Is it a good idea to capture self in Logger calls?
- Is it safe to log non value-type objects such as class instances?
Thanks for clarifications.
the "later" part concerns us
The tl;dr here is that you don’t have to worry about this. However, the reasons why you don’t have to worry are interesting, so I thought I’d dig into that.
To start, let’s consider the C API:
os_log_t log = …
double answer = 42.0;
os_log_debug(log, "answer: %f", answer);
os_log_debug is actual a macro that expands to something like this:
os_log_t log = …
double answer = 42.0;
if (os_log_type_enabled(…)) {
_os_log_debug_impl( … __dso_handle, … format, answer, … );
}
There are two things to note about this code:
- Evaluation of the arguments in done within the
ifstatement, so they don’t get evaluated if this log point is disabled. That’s good to know in and of itself, but it’s also impacts on Swift. I’ll come back to that later. - The underlying system routine,
_os_log_debug_impl, is passed__dso_handle. This is fundamental to how the system log works.
The above example doesn’t actually record any strings. Rather:
- It records arguments, like
answer, in binary format. In this case the argument is a%f, so it records the eight bytes of the Cdouble. - The format string,
answer: %f, isn’t recorded as a string. Rather, the system log records the Mach-O build UUID [1] of the calling code and the offset of the string within that Mach-O file. The system uses the__dso_handleto get this UUID. It also forms the base address for the string offset calculation.
Note This optimisation radically reduces the size of each system log entry. It also explains why it’s bad to wrap the system log API. See Your Friend the System Log for more on that topic.
When an app, like Xcode or the Console, displays a log entry, it gets the format string, applies the arguments, and displays the result. This produces some interesting side effects. For example, Xcode renders the number as 42.000000 but the specific format is a decision made by Xcode. It could just as easily render it as 42.0.
So, your concern about when the log message gets rendered is unfounded, because that’s actually done by the log client.
However, it’s still important to think about when arguments are evaluated. As I’ve shown above, in the C API that’s synchronous. That is, the arguments are evaluated on the caller thread before the os_log_debug ‘function’ returns.
The same is true in the Swift API, but there’s a wrinkle. If you dig into the API, you’ll see that it uses Swift’s @autoclosure attribute. This is what allows for the the argument to only be evaluated if logging is enabled, just like in C.
Note that the closure is not escaping, so if the closure is to be evaluated it must be evaluated synchronously, before the debug(…) method returns. So, again, no need to worry about concurrency.
However, the use of @autoclosure does explain the requires explicit use of 'self' error you’re seeing.
Share and Enjoy
—
Quinn “The Eskimo!” @ Developer Technical Support @ Apple
let myEmail = "eskimo" + "1" + "@" + "apple.com"
[1] For more on Mach-O build UUIDs, see TN3178: Checking for and resolving build UUID problems.
[3] The public API for this, in the OSLog framework, doesn’t give you that level of control. The framework itself always returns a fully rendered message in the composedMessage property. Xcode, Console, and the log tool use an alternative path to get at the message components, one that’s not available via the public API.
Note that the composed in composedMessage hints as to the existence of this alternative path to get the ‘decomposed’ message.