Logging and Signposting Taxonomy in Concurrency

Having a file provider extension with multiple domains and processes and even more enumerators logging in parallel can become a mess. Leveraging the subsystem and category fields to the rescue.

In the beginning I actually did not know how to name this post. In a nutshell, it is about keeping an overview of what is happening when there are many objects logging and signposting concurrently. The practical use case is a file provider extension which has multiple domains.

• The system launches at least one process per replicated file provider extension. This happens on macOS and iOS, as far as we observed.
• Every process is active independently from the others.
• There may be multiple enumerator objects per process working at the same time.
• Process IDs may suffice in short term differentiation. In example in macOS’ Console.app while debugging. But those identifier change with the lifecycles of the processes and are not stable unlike the file provider domain identifiers.

It will get hard to understand what is going on from logs if they all spam concurrently without further distinction. Our file provider extension processes perform their own synchronizations, so it can become a mess.

Context Objects

My take on this is: Have a logging context struct which is passed down the whole call stack starting with the file provider extension implementation. If you know a better idea, please let me know. However I also vaguely remembered it from my brief time on working on OpenERP and Odoo where context objects were used, too. Anyway, this is a simplified and not necessarily complete example of how such context object can look like:

public struct LoggingContext: Sendable {
    public let subsystemIdentifier: String?
    public let categoryIdentifier: String?
}

The properties are optional because not every object may have a context which requires further details to identify it. For example the file provider extension type is a unique object in its process. It can have the file provider domain identifier in its subsystem string but that already is everything required to distinguish it from the other logging processes.

Pass this logging context in every initializer of subordinate types. They then can initialize their Logger and OSSignposter objects appropriately. I know, this involves some boilerplate code. This whole thing still is kind of an exploratory process and not peak wisdom.

We use the bundle identifier for as subsystem string for Logger and OSSignposter objects. The optional and additional identifiers of the context object serve for further distinction. An initialization without the contextual information can look like this:

logger = Logger(subsystem: Bundle.main.bundleIdentifier ?? "", category: "Example")
signposter = OSSignposter = OSSignposter(subsystem: Bundle.main.bundleIdentifier ?? "", category: "Example")

Note: I try to avoid forced unwrapping as much as possible, hence the nil-coalescing operator for the very unlikely nil value for the bundle identifier. Should it ever fail, then at least not cause a crash for this rather non critical thing.

Subsystem and Category Strings

Getting the contextual information in there can result in cumbersome expressions. I have created functions which wrap the composition of the subsystem and category strings. For example, the function to create the subsystem string:

public func makeCategory(type: String, context: LoggingContext?) -> String {
    if let identifier = context?.categoryIdentifier {
        return "\(type) (\(identifier))"
    }

    return type
}

public func makeSubsystem(_ context: LoggingContext?) -> String {
    let bundleIdentifier = Bundle.main.bundleIdentifier ?? ""

    if let identifier = context?.subsystemIdentifier {
        return "\(bundleIdentifier) (\(identifier))"
    }

    return bundleIdentifier
}

It either just uses the bundle identifier or appends the detail information in the pattern of “de.i2h3.example (ContextualIdentifier)”. This reduces the initialization code to this:

logger = Logger(subsystem: makeSubsystem(context), category: makeCategory(type: "NameOfTheTypeBeingInitialized", context: context))
signposter = OSSignposter(subsystem: makeSubsystem(context), category: makeCategory(type: "NameOfTheTypeBeingInitialized", context: context))

Macros Everywhere

Okay, I was still not satisfied with this amount of redundant code and I really like macros, so I:

1. created a @ContextualLogging member macro the automatically augment the annotated type with the logger and signposter properties. Additionally, it also adds a static property which automatically defines the logging type name as a string literal.
2. created the #makeContextualLogger and #makeContextualSignposter expression macros to reduce the initialization calls to Logger and OSSignposter to something more on point.

In Action

All together in action, it can look like the following snippet which gives away a better impression:

@ContextualLogging
class ContextuallyLoggingExample {
    init(loggingContext: LoggingContext? = nil) {
        logger = #makeContextualLogger(loggingContext)
        signposter = #makeContextualSignposter(loggingContext)
    }

    func sayHello() {
        logger.notice("Hello!")
    }
}

I would like to point out that the expression macro arguments are optional to implement. Initially I had #makeContextualLogger and #makeContextualSignposter without any argument. Their expansion reliably assumed always the same name of the logging context argument. However, SwiftFormat then always removed the argument because it was unused from its point of view. I wanted to achieve a compromise to not restrict SwiftFormat which still keeping the code short and introduced the logger context argument to the macros.

This will result in distinctive log messages in the Xcode console as well as the Console app of macOS. It enables convenient filtering to narrow logs down to the relevant objects.

standard    10:14:16.460195+0100    ProviderForMacOS    com.example.product.provider.macos (97E1016F-F81E-4BC3-B836-F982F72C9323)  Enumerator (NSFileProviderRootContainerItemIdentifier)   Enumerated 6 items at page 0.

Even better: visualizing signposts in Instruments, objects are distinguished, too.