MacKuba

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

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)

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

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

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

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

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