Unified Logging and Activity Tracing
Last year Apple had introduced big changes in logging system of all the updated platforms (iOS 10, watchOS 3, tvOS 10, macOS 10.12 ): old ASL and Syslog APIs are now redirected to new Unified Logging under the hood, Activity Tracing is greatly improved. This is a story of how I’ve adopted them to debug an extremely asynchronous watchOS3/iOS10 application written on Swift3.
Why Unified Logging?
Meet Fox: iOS10 app with watchOS3 extension. Fox is tracking user’s motion activity via Apple Watch’s accelerometer, transfers raw data to phone and then — to server for further Big Data Analyze. The tricky thing: user participates in medical study and his life is very hard, so Fox is not supposed to bother him during the day, it should run in background and gather data silently.
As for watchOS3, watchapps are considered mostly foreground apps, background execution is intended only to update UI. Background execution time can be gained once an hour for apps in Dock and twice an hour for apps with owning an active Complication on current watchface.
In each background task Fox should request accelerometer data from Motion Sensor (which is done asynchronously), write it to file, place to transfer queue, wait until it will be transferred to iPhone and get response that transfer passed without faults. Also, we want to improve performance by running this request-data-file-transfer-response in N concurrent Operations. And we want logs to debug whole thing.
First impulse was to use one of popular 3rd party frameworks like Crashlytics or Cocoalumberjack, as most iOS projects do.
It was disappointing: Crashlytics still lacks watchOS support, and imagine what a mess I’ve witnessed in Cocoalumberjack’s ordinary textual log, when four threads and dozen of callbacks started pushing messages to the end of the file simultaneously.
Another problem was observer effect: each message written via Cocoalumberjack took CPU time, changed timing of whole algorithm and less amount of data was being processed during background task. watchOS3 has spartan restrictions: OS will not give you background execution time if your last background task took too long or used too much of a CPU. Such logging made more harm than profit.
So, I needed fast logging system, comfortable for asynchronous code, with unpopular Apple platforms support. I’ve decided to go to the roots and try native Unified Logging and Activity Tracing.
Logging
Features, as described in WWDC Session 721:
- Categorization and filtering: every message has Subsystem, Category, one of four Levels (Default, Info, Debug, Fault, Error), Enabled flag and Destination (Disk or Memory).
- Privacy: prevents accidental leak of Personally Identifiable Information to stored logs by replacing dynamic strings, collections, arrays with a <private> word. This behavior can be overriden on a per-parameter basis.
- Usability: logging system collects caller information for you, builtin type specifiers simplify message preparation.
- Performance: minimal observer effect. Data stored in binary .tracev3 files in /var/db/diagnostics/ and transferred in .logarchive files (both file formats can be opened with Console.app updated in macOS Sierra). Whole system’s log is written to one place.
Despite of bunch of C-functions described in WWDC Session slides, in Swift usage is extremely straightforward: one os_log function accepts message as a StaticString (known at compile-time) with placeholders for arguments, arguments themselves, OSLog if you want to use non-default Subsystem and Category and enum for a log level. Only message string is obligatory:
func os_log(_ message: StaticString,
dso: UnsafeRawPointer? = #dsohandle,
log: OSLog = default,
type: OSLogType = default,
_ args: CVarArg…)Except usual format specifiers (familiar to Objective-C developers), message’s StaticString can include additional formatter:
Privacy is handled on a parameter by parameter basis: scalars and static strings are assumed to be public, while dynamic strings, collections, and objects are assumed to be private. This behavior can be overridden on a per-parameter basis:
"%{public}@" or "%{private}d" or "%{public, uuid_t}.16P"Example:
Activity Tracing
Reasoning about what the heck happened in logs of asynchronous code is often very hard. Activity Tracing was first introduced in 2014 for iOS8 and OS X 10.10 to eliminate this problem. In 2016 it was greatly improved and aligned with new Unified Logging system.
Before diving into code, try to get the idea of what log will look like in the end:
The top half of the screen shows tree of Activities — who group together all the executed code, no matter on what queue and in what processes. Activities have a tree-like hierarchy.
For example, on Fox’s log screenshot above you can see:
- Handle task activity (started when watchapp gets background task execution chance)
- which starts Reschedule activity (which schedules next background task)
- who starts concurrent execution of four Tasks (who defines parameters of data they want to get from Motion Sensor)
- each of those starts Get Data activities (which requests data from CoreMotion asynchronously and wait for callback)
- which in case of success send message to wake up iOS counterpart app, get callback
- and then send data in file and get callback on arrival.
Asynchronous. Code. With. Dozen. Of. Callbacks.
The bottom part of the screen shows all the log messages inside chosen activity. Pay attention that not only Fox’s messages are shown, but also of all Apple’s frameworks called from my code (Foundation, WatchKit, etc) and all other processes involved into work (locationd, Carousel, etc).
Cool? I was fascinated by this system. The sad thing is that Swift3 (as for January 2017) has no integration for Activity Tracing, and you have to use wrapper. Thanks to
, we have one, which is pretty lightweight and straightforward to use:How to analyze it
Unified Logging’s logs can be opened with new Console.app (updated in macOS Sierra), as they are written in binary format. If you’ll connect iPhone to your mac and run Console, you can see whole system’s real-time console output, including all paired and connected watches’.
In order to get logs out from Apple Watch or iPhone, you should use Apple’s sysdiagnose tool. It has pretty good instruction on Profiles and Logs page. Long story short: you have to install special profiles to all the devices you want to get logs from, reproduce issue, trigger system diagnose by pushing key-chord, synchronize devices with your computer and find whole system diagnostic report in special folder. As far as I’ve understood, logs are no longer readable from code.
This text was written in January 2017, in respect of Swift3, Xcode8.2.1, iOS10, macOS Sierra and watchOS3.
