Apple has dramatically revamped its standard logging mechanism. Unified Logging, available in macOS 10.12 and iOS 10, replaces various file-based logging approaches with a centralized, database-backed repository for log information of all levels of interest.
The big win, both for developers and for users, is performance. Where the simple act of logging some debugging information used to have enough of a cost to dissuade rampant use, the new system makes it so cheap that developers inside Apple and out are being encouraged to “log like the dickens” in the name of generating more evidence for posthumous debugging. The new system also offer impressive data mining abilities, making it far easier to filter for what you’re looking for and to track logging information across specific activities, even if the activity spans multiple processes.
The two big losses, in my opinion, are that the sheer size, number, and variety of logging messages makes it impractical for users to skim the console for “real problems,” and that the resulting logging archives are so large that it’s impractical to casually include them with bug reports to Apple or 3rd party developers.
The WWDC session on the topic goes into detail on these points, but perhaps most useful for framing my complaints here are Apple’s stated goals for the revamp:
- One common, efficient logging mechanism for both user and kernel mode
- Maximize information collected while minimizing observer effect [the phenomenon that enabling or adding logging changes the behavior of the system you are trying to understand]
- We want as much logging on all the time as possible
- Design privacy into the system
Two of the stated goals, “maximizing information collection,” and “as much logging on all the time as possible,” exacerbate the problems of there being so much log data that it’s both difficult to skim, and cumbersome to share.
Imagine a society in which all packaging has been transformed into fast-composting, biodegradable materials. Your soda bottles, snack wrappers, cigarette packages, etc., all biodegrade to dirt within 48 hours of use. What a boon for the world: the major, global problem of trash accumulating in our towns and environment would be gone. Poof!
Or would it? When “littering has no cost,” I suspect that we’d face a new problem: far more people would litter. Why bother finding a place to throw out that bottle, when nature will take care of it in within 48 hours? Multiply this attitude out over even a small portion of the world’s billions of people, and we’d be guaranteed to be buried in trash. All trash that will be gone in 48 hours, mind you, but constantly replenished with a fresh supply.
I think this metaphor points to a similar problem with unified logging: the sudden onslaught of “low cost logging” has left our developer society unprepared in some specific ways to deal with the consequences of the new reality.
So, how can we, and Apple fix this? We need specific solutions that make skimming for problems, and sharing pertinent log data easier, yet don’t impact the very positive goals outlined by Apple above. Here is my advice:
- Don’t litter the logs. Just because you can log it, and just because doing so is cheap, doesn’t mean there isn’t a cost. Some of the recurring log messages littering my Console arrive at a rate of thousands per minute. There may be good arguments that certain subsystems, in certain states, should log this extensively if the resulting data will justify easier diagnosis of problems, but much of the junk I see are redundant reiterations of relatively useless information:
Not switching as we're not in ~/Library/Keychains... ... CSSM Exception:... ... Etc. Etc. Etc.
Some of these seem to be well and truly noise, but some of them, even if they seem highly redundant and noisy to me, could in fact represent useful logging if you happened to, for example, be tracking down a subtle bug in Apple’s security libraries. That’s fine, I’ll accept that some amount of log diarrhea in the name of better software, but only if the following accommodation is made…
Annotate high-frequency logs for easier filtering. The logging system offers a variety of tools for annotating log messages, but even internal Apple groups do not seem to use these extensively or appropriately. The system supports the notion of three levels of log message: default, info, and debug. Only the “default” level messages are displayed by default in the Console app, yet all of the above-described garbage is displayed in that default mode. The Console will become significantly more useful when the worst offenders have marked their messages for severity, subsystem, and category so that they can be effectively omitted from the default view, and so that they can be mined later for use by folks who can actually make sense of them.
Generate context-specific sysdiagnoses. One of the worst practical outcomes of unified logging is that capturing a “sysdiagnose” on my Mac now generates a compressed archive that is still larger than 400MB. These archives are typically requested by most groups at Apple in response to bug reports, regardless of how severe the bug is or how readily reproducable it appears to be. In the world of Apple bug reports, sysdiagnoses are treated like lightweight bits of information that should be appended to every issue, except they’re now anything but lightweight.
All the annotation work advised above should really pay off when Apple provides a streamlined mechanism for capturing sysdiagnose information pertinent to a specific subsystem or product. The company already offers product-specific advice for capturing log information, sometimes requiring the installation of custom profiles and other shenanigans. The lightweight unified logging system empowers Apple to both require that internal groups properly annotate their log messages and to facilitate smarter gathering of that data.
Currently if you want to capture a sysdiagnose at any time a Mac, you simply press Ctrl-Opt-Cmd-Shift-Period. On an iOS device it’s done by holding both volume keys and the power key, but you have to enable logging first with a custom profile. This shortcut will generate one of those mondo 400MB style sysdiagnose archives, which you can upload to attach to your bug reports in your copious spare time.
I envision a prompt that appears after invoking the existing shortcut, or else a new shortcut for “interactive sysdiagnose” where you could specify the category of bug you are reporting. The prompt would list categories correlating to groups at Apple who had done the work of providing streamlined log filtering data that will effectively strip out all the useless (to that group) noise from your log data.
In fact, sysdiagnose already takes a “process” parameter when invoked from the command line, and my understanding is that this enables it to capture data that is pertinent to the target process. The unified logging system seems to provide the infrastructure for even smarter capturing along these lines.
I realize that in this time of flux, where much log data is not properly annotated, there is still an incentive for many groups to capture as much as possible and sort it out on Apple’s end. These groups should know, however, that the larger the sysdiagnose archive you ask users to upload, the lower the chances they will bother actually following through on filing the bug or on providing the pertinent information you have requested.
Annotate specifically for user-concerning issues. Power users on the Mac have, for years, counted on being able to skim the console log for information that might explain a slow Mac, persistent crashes, or other inexplicable behavior. Given the huge increase in number of log message and the lackluster annotation of these messages by Apple, the Console app is effectively useless to users for this purpose.
On top of getting the annotation right in general, I think a new special level of log message should be created, indicating particular concern to end-users. These would identify log messages that developers specifically think users should take notice of and follow up about. I mentioned there are three basic levels of log message: default, info, and debug. On top of that, there are two special levels called “fault” and “error”, which can be filtered on in the Console, and which receive special treatment from the logging system.
These special levels seem close to what users might find interest in, but they’re not quite right either.
A “user interest” level of logging message would facilitate the kind of high level skimming that seems impossible in Sierra today. These log messages would convey information that a user might gain some insight from. They would stand in stark contrast to the noise of messages like these, from the filecoordinationd process:
Claim D32EDEBE-C702-4638-800C-E4BAB9B767F3 granted in server
Nobody knows what a claim is, or cares whether it was “granted in server” … unless they are actively debugging filecoordinationd. On the other hand, a message indicating the failure to grant a claim “because the disk is full,” could be very useful to users indeed.
I realize the line could be difficult to draw in some circumstances, but a huge number of messages currently being logged are obviously not of user interest. Perhaps then, the opposite approach could be taken, and log messages could be annotated as being specifically useful for posthumous, internal debugging by developers.
I tell you, things are bleak. We’re swimming in a morass of useless console noise, and there is little we can do about it. There is room for optimism however, as the logging infrastructure is good, and seems to support many thoughtful measures that could attenuate the problems and make the system more useful and less cumbersome to developers, end-users, and well-meaning bug reporters.
The console is littered with trash. Sure, it will biodegrade in 48 hours, but that doesn’t mean we shouldn’t be concerned with cleaning it up. A combination of more thoughtful logging, proper annotation, and appropriate filtering will get us out of this mess.