MacKuba

Kuba Suder's blog on Mac & iOS development

Logging

App ClipsAppKitExtensionsFoundationLocationLoggingMacMapsPerformancePhotosPrivacySafariSwiftSwiftUIUIKitWatchKitWWDC 14WWDC 16WWDC 18WWDC 19WWDC 20

View as index

Explore logging in Swift

Categories: Foundation, Logging, WWDC 20 0 comments Watch the video

Xcode 12 introduces new APIs for the unified logging system:

import os

let logger = Logger(subsystem: "com.example.Fruta", category: "giftcards")
logger.log("Started a task")

It's now much easier to pass arguments to logs using new Swift interpolation than the old os_log API with C-style formatters:

logger.log("Started a task \(taskId)")

Like in os_log, it does not generate the resulting formatted string at the moment of logging, but stores an optimized representation and defers formatting to a later moment

You can pass any values like numeric types, ObjC types that implement description and any type conforming to CustomStringConvertible

Non-numeric data is private by default:

logger.log("Paid with bank account \(accountNr)")
// -> Paid with bank account <private>

To actually display the values, use the privacy: parameter:

logger.log("Ordered smoothie \(smoothieName, privacy: .public)")

You can also log private data in an obfuscated form, but hashed in such a way that each value gets its unique hash which you can track through a chain of logs:

logger.log("Paid with bank account: \(accountNumber, privacy: .private(mask: .hash))")
// -> Paid with bank account <mask.hash:'CSvWylJ63...'>

Collecting recent logs from a connected device to a file:

log collect --device --start "2020-06-22 9:41" --output fruta.logarchive

Log levels:

  • debug – useful only during debugging
  • info – helpful but not essential for troubleshooting
  • notice (default) – essential for troubleshooting
  • error – expected errors
  • fault – unexpected errors, assumptions that weren’t true, potential bugs

The Logger has a separate method for each log level:

logger.debug(…)
logger.error(…)
// etc.

Take into account that not all logs are persisted after the app finishes execution, some can only be live streamed

debug  ⭢  not persisted by default

info  ⭢  saved to memory, only persisted if collected using log collect before they disappear

notice  ⭢  persisted up to a storage limit, older messages are purged after some time

error, fault  ⭢  persisted for a longer time than notice messages (typically a few days)

The level also affects logging performance: debug logs are the fastest, error and fault are the slowest

It’s safe to call even some slower code within log messages that will not be logged – the code isn’t run unless the log is enabled:

logger.debug("\(slowFunction(data))")

Logger provides a number of built-in formatters that let you customize how an interpolated value is displayed:

logger.log("\(cardId, align: .left(columns: 5))")
logger.log("\(seconds, format: .fixed(precision: 2))")
logger.log("\(data, format: .hex, align: .right(columns: 4))")

+ others like decimal, exponential, octal

Existing os_log(…) function also accepts the new interpolating parameters (when running on latest OS versions)

Measuring Performance Using Logging

Categories: Foundation, Logging, Performance, WWDC 18 0 comments Watch the video

Signposts – a new feature of the os_log API

Useful for debugging performance issues

Integrated with Instruments, which can visualize activity over time using signposts

Signposts allow you to mark the beginning and end of a piece of work and mark it with some kind of label

import os.signpost

let refreshLog = OSLog(subsystem: "…", category: "…")

os_signpost(.begin, log: refreshLog, name: "Fetch Asset")
// …do actual work…
os_signpost(.end, log: refreshLog, name: "Fetch Asset")

Ranges of signposts with different names can overlap – e.g. you can have one signpost covering the whole process and smaller signposts covering specific single tasks that it consists of:

os_signpost(.begin, log: log, name: "Load Data")

os_signpost(.begin, log: log, name: "Fetch Asset")
// …
os_signpost(.end, log: log, name: "Fetch Asset")

os_signpost(.begin, log: log, name: "Parse JSON")
// …
os_signpost(.end, log: log, name: "Parse JSON")

os_signpost(.end, log: log, name: "Load Data")

If you run multiple tasks of the same kind, to let the system differentiate between them and know which begin matches which end, you can add a “signpost ID”:

os_signpost(.begin, log: log, name: "Load Data")

for asset in assets {
    let spid = OSSignpostID(log: log)

    os_signpost(.begin, log: refreshLog, name: "Fetch Asset", signpostID: spid)
    // …do actual work…
    os_signpost(.end, log: refreshLog, name: "Fetch Asset", signpostID: spid)
}

os_signpost(.end, log: log, name: "Load Data")

You can also pass your model object when generating the signpost ID – then it will always use the same signpost ID for the same object, and you don't have to store the signpost object, just your model:

let spid = OSSignpostID(log: log, object: asset)

There is also an option of passing an additional string argument to begin/end to provide some context (e.g. to differentiate between different possible ways to finish an activity, like success/failure)

The string also accepts format arguments like os_log:

os_signpost(.begin, log: log, name: "Compute Physics",
    "Calculating %{public}s: %d %d %d %d", description, x1, y2, x2, y2)

Apart from marking the beginning and end, you can also mark specific points in time during the process using the .event signpost type:

os_signpost(.event, log: log, name: "Fetch Asset",
    "Received chunk of data, size %d", size)

Signposts are very optimized internally, they’re built to minimize the time spent when logging, same as the whole os_log API

This means you can emit a lot of signposts even in a very tight window, when investigating a performance bottleneck

If you still really want to enable or disable some signpost logs based on some conditions, you can swap your logger object with OSLog.disabled:

let refreshLog: OSLog

if ProcessInfo.processInfo.environment.keys.contains("SIGNPOSTS_REFRESH") {
    refreshLog = OSLog(…)
} else {
    refreshLog = .disabled
}

To conditionally disable some expensive code that is only useful for debugging, you can check the signpostsEnabled property:

if refreshLog.signpostsEnabled {
    let information = collectInfo()
    os_signpost(…, information)
}

All APIs are also available in C & ObjC:

#include <os/signpost.h>

os_signpost_interval_begin()
os_signpost_interval_end()
os_signpost_event_emit()
os_signpost_id_t
OS_LOG_DISABLED

Use formatter %{xcode:size-in-bytes}u to let Xcode & Instruments know that the logged value is a byte size of some data

→ This is one of so called “Engineering types” – find more in the Instruments Help menu, in the Instruments developer guide

Instruments:

Use the “os_signpost” instrument to profile using signposts

After recording some data, you can see the signpost names in the sidebar on the left and signpost ranges with the optional begin/end comments marked on the chart

In the bottom pane you can see count and duration statistics, grouped by category, signpost, id and comment

Clicking the arrow button next to a specific message row shows you a list of all instances of this specific message (selecting them highlights them on the timeline)

For metadata like logged byte sizes of downloads, you can choose “Summary: Metadata Statistics” to see total/min/max/avg of each type of value

Live streaming signpost logs to Instruments (“Immediate mode”) adds some overhead, so if you want to avoid that while debugging some performance-critical code, click and hold the Record button to access recording options and change mode to “Last n seconds”

Points of interest:

Points of interest is a special log category of OSLog

It’s meant for logging important actions taken by the user, like opening some specific screen

Normal os_log logs and signpost logs logged to this category appear in a special separate Instruments timeline, which lets you visualize what was happening in the app at the moment when something happened on other charts like CPU usage

Custom Instruments packages:

You can now build your custom Instruments packages, defined as an XML file in a separate target, which appear as a new kind of template when starting Instruments

This lets you process and present collected signpost data in a different way that makes sense for the specific problem you’re analyzing

Fix Bugs Faster Using Activity Tracing

Categories: Foundation, Logging, WWDC 14 0 comments Watch the video

⚠️ The APIs mentioned in this talk seem to be somewhat abandoned – they were never made available to Swift, some things have been deprecated or have stopped working.


Apple has been adding a lot of tools for asynchronous development, like XPC, GCD, NSOperation

However, splitting work between different threads and especially between different processes makes it difficult to debug and diagnose issues

A single call to a system API might result in multiple system daemons calling each other to execute this single activity

Current logging mechanisms are insufficient, because they lack context showing how you got to the place where something happens

When something goes wrong in one of the systems involved, the whole activity fails, but it’s not clear where to look for the problem

Goals of this new tool:

  • reduce the time guessing what happened where, how did it get there and why
  • understand interaction of multiple actions over time
  • it should be lightweight and easy to use

Activities

Activity = a set of work triggered by a specific action, going across multiple systems cooperating to realize a specific goal

There’s a new system daemon diagnosticd that handles the activity tracing for all processes

Each activity has an identifier (AID) automatically propagated across the system

Activities are automatically created by UIKit and AppKit for UI actions

When you e.g. press a button in the UI, AppKit or UIKit automatically creates a new activity with some unique name, calls os_activity_start() on it, calls your IBAction handler, and then calls os_activity_end() at the end

You can also create activities explicitly:

os_activity_initiate("Activity Name", flags, ^{ … });
  • name must be a constant string
  • another variant available without a block
  • included in <os/activity.h>

Detached activity (OS_ACTIVITY_FLAG_DETACHED) = a new activity that’s not a subactivity of the current one, but a completely independent activity

Breadcrumbs

Breadcrumb = a user-facing or user-initiated action that triggered an activity, e.g. “Send an email”

A way to label activities meaningful to you

Adding a breadcrumb:

os_activity_set_breadcrumb("composing email");
  • name must be a constant string
  • only supported in the main process binary, not in libraries or plugins

⚠️ Replaced later with os_activity_label_useraction, only for activities started from IBActions

Trace messages:

Trace message = a single log in a given system as a part of an activity

New API to add trace messages to the current activity

Messages are stored in an in-memory ring buffer

Different behavior for production code and debugging

os_trace("Something happened at level %d", index);
  • only scalar format types allowed (ints, longs etc.)
  • strings and characters are *not* supported for privacy, security and performance reasons
  • included in <os/trace.h>
os_debug_trace("Open socket %d total time %f", sock, time);
  • version for debug logging
  • only actually logged if you’re in the debug mode, ignored in release mode
  • records more information – increased buffer size
  • you can enable debug mode at launch by setting env variable OS_ACTIVITY_MODE=debug

If you want to pass some additional data with a trace message, you can use os_trace_with_payload:

os_trace_with_payload("Interface: %ld", index, ^(xpc_object_t dict) {
    xpc_dictionary_set_string(dict, "interface_name", ifname);
});
  • blocks are only called and have their data recorded if the activity logs are being currently live streamed to a log viewing tool
  • uses XPC to deliver data to diagnosticd
  • you can enable stream mode with an env variable OS_ACTIVITY_MODE=stream

⚠️ Replaced later with os_log

Crash logs now include information about the current activity at the moment of the crash (name, running time etc.), the last few breadcrumbs, and recent trace messages from that activity (!)

⚠️ They don’t anymore :(

Logging errors into trace messages:

os_trace_error("Interface %ld failed with error %d", ifindex, errno);
  • soft errors, something that went wrong
os_trace_fault("Invalid state %d - will likely crash", state);
  • fatal errors, this shouldn’t happen, about to crash
  • sends trace messages from the process’s local buffer to diagnosticd

Limits:

  • format string cannot exceed 100 characters
  • formatted trace message string also has a limit, will truncate if exceeded
  • up to 7 parameters allowed
  • process ring buffer size depends on the platform and debug/release mode

Debugger: thread info includes current activity info and last trace messages

ostraceutil command line tool – live streaming of activity trace from a process (by name or pid)

⚠️ Replaced later with log

Tip: think about privacy when adding trace messages – never trace identifying information about a user or device

Unified Logging and Activity Tracing

Categories: Foundation, Logging, WWDC 16 0 comments Watch the video

Design of the API:

Creating one common efficient logging mechanism that can be used in user and kernel mode

Maximize information collected while minimizing the “observer effect” (affecting the program and the analyzed issue by adding logging)

Minimal footprint during the call – a lot of processing is deferred to some later time, e.g. to the moment when the information is displayed when viewing logs

Managing message lifecycle – different kinds of messages are kept around for a different duration depending on how important they are

We want as much logging happening as possible all the time without it affecting the performance of the system

Designed for privacy from the ground up

New ways of categorising and filtering log messages, so it’s easier to find messages you care about

Caller information is collected automatically, so no need to add info about the file/line etc. to the message

Built-in type specifiers that help with message formatting

New console app and command line tool

Supported across all platforms and simulators

Legacy APIs (NSLog, asl_log_message, syslog) are all redirected to this new system (if you build on the latest SDK)

All log data will be in a new location and a new format

Log data is kept in a compressed binary format, as .tracev3 files

Stored in /var/db/diagnostics and /var/db/uuidtext

You must use new tools to search the logs, since the data is binary and not searchable using grep etc.

New .logarchive format for sharing logs exported from the system log

Subsystems and categories:

Log messages can now be associated with a subsystem (e.g. an app, target or module) and a category (e.g. a section of an app), which can be used to control how messages are filtered and displayed

A subsystem can have multiple categories, and you can use as many subsystems and categories as you need

Each log message has a level:

  • 3 basic levels: Default, Info, Debug
  • 2 special levels: Fault, Error

You can set per category, per subsystem or globally logs of which level up are enabled (Default and up are always enabled) and which are stored to disk or to memory (memory log keeps a temporary space for logs that are overwritten much faster than disk logs)

Behavior can be customized globally using profiles or the log command on macOS

Default configuration is:

  • Logs of level Default and above are saved to disk
  • Info logs are enabled and stored in memory
  • Debug logs are disabled

Privacy:

The new logging system is designed to prevent accidentally logging sensitive personal information to the logs

Dynamic data injected into log messages is assumed to be private, static strings are not private

Errors and faults:

The system collects some additional information when logging errors and faults to help with investigating issues

Error  ⭢  an issue discovered within the given application/library

On an error, all previous logs from this process logged to memory are saved to disk so that they can be kept for longer

Fault  ⭢  a more global problem in the system

On a fault, all logs from this process and other processes involved in the same activity are saved to disk, plus some other system information is collected

Faults and errors and the information collected with them are saved to separate log files, so the normal logs don’t push them out

How the system works:

Within each process there are some buffers for logging messages

There is a logging daemon logd in the system, when the buffers fill up it compresses them into a larger buffer that it maintains

If you request a live stream of logs, the logs are sent to diagnosticd daemon which sends them to the client

There is a large performance hit when doing live streaming of logs, since all the optimizations can’t be used

The Console app:

Sidebar shows different kinds of log sources and connected devices

“Activities” button lets you turn on activities mode that shows a path of logs connected to a specific activity

When streaming live, by default Debug and Info messages are not printed – enable them in the menu to see them

Colored dots on the left side show message level (no dot = default level)

Use left/right arrows to expand and collapse messages in the list

To filter messages, you can search for a string in any field, or you can ask to exclude rows from a given process/subsystem/category etc.

Use the context menu to show/hide messages of the same category/process etc. as the highlighted one

Type e.g. “proc:myapp” to quickly search for process = myapp

You can save frequently used searches using the “Save” button, they’re added to the filter bar above the table

Activities can also be filtered in a similar way (however, they don’t have subsystems, categories or levels)

New APIs for logging:

os_log – writes a log of default level

os_log_info, os_log_debug, os_log_error, os_log_fault – different levels

os_log_create – creates a log object that you can customize

os_log_t log = os_log_create("com.yourcompany.subsystem", "network");

Then you pass this log object to the calls listed above:

os_log(log, "Something happened")

You can have multiple log objects for different categories and use the right one for each log

If you don’t want to have a custom subsystem/category, pass OS_LOG_DEFAULT as the log object

Log API includes built-in formatters for various types

Converting a value into a string representation is deferred to when the message is displayed in the Console

Timestamps: %{time_t}d

Error codes: %{errno}d

Arbitrary binary data: %.*P

etc.

Privacy:

Privacy is handled on a per parameter basis

Static strings are assumed to be public, dynamic strings and objects are assumed to be private unless you override it

Overriding an object to be public: %{public}@

Overriding a simple value to be private: %{private}d

You can combine privacy and formatting: %{public, uuid_t}.16P

Activities:

Activities are now objects that you can store and reuse

You can easily control the relationships between activities

os_activity_create – creates an activity object (you can pass it a parent activity to create a hierarchy)

os_activity_label_useraction – marks the activity as a “user action” (initiated by the user)

os_activity_apply(activity, ^{ … }) – executes that block as a part of that activity

os_activity_scope(activity) – executes everything until the closing brace as a part of that activity

The log command line tool:

Same functionality as the Console, but from the command line

log stream – live streaming logs

log stream --predicate 'eventMessage contains "my message"'

log show system_logs.logarchive – shows logs from a file

log config --mode "level:debug" --subsystem com.mycorp.app – enable debug logging for the given subsystem

Logging tips:

Don’t add any extra whitespace or formatting to logs

Let the SDK do string formatting

Avoid wrapping os_log calls in some custom APIs (or use macros, not functions)

Only log what’s needed from arrays and dictionaries, they can take a lot of space on disk

Avoid logging in tight code loops

How to use various levels:

  • default – for normal logs about what the app is doing
  • info – for additional info that gets stale quickly and will only matter in case of an error
  • debug – for high volume logging during development
  • error – to capture additional information from the app
  • fault – to capture additional information from the system

Collecting logs for bug reports:

The preferred method is sysdiagnose

Sysdiagnose collects logs in a file named system_logs.logarchive

You can use a specific key combination on the given device to trigger a sysdiagnose, and then transfer using iTunes

Deprecations:

All ASL logging APIs are deprecated

Older activity APIs: os_activity_start, os_activity_end, os_activity_set_breadcrumb, os_trace_with_payload