Логи в iOS, эпизод 1: os_log27.09.2022 17:01

Представьте, что вы садитесь делать новый проект для iOS/iPadOS/macOS/tvOS/watchOS. Очень скоро сталкиваетесь с первым багом и, чтобы его понять и исправить, добавляете логи — вызываете print() тут и там. Баг исправили и часть логов убрали, а часть оставили на будущее — полезные, ещё пригодятся.

Спустя пару месяцев работы над проектом консоль в Xcode превращается в водопад из логов. В них сложно разобраться, в них невозможно ориентироваться. Принимаете это как данность и в новые логи для удобства добавляете какие-то маркеты по типу "----->" или ещё что-нибудь в этом духе — так их можно будет различить в бесконечном потоке.

Это работает, но ровно до тех пор, пока не перестаёт. В этот момент не выдерживаете и чистите большую часть бесполезных, по вашему мнению, логов, случайно зацепляя вместе с ними и полезные. Теперь у вас остались какие-то логи, которые что-то показывают. Какова их ценность — не ясно.

Давайте расскажу, как Apple предлагает решать эту проблему.

Console.app

Apple предлагает читать логи в специальном приложении — Console.app, которое встроено в macOS. Но если его запустить и выбрать устройство с вашим запущенным приложением, то вы увидите ещё бо́льшую портянку сообщений: тут и системные логи, и логи приложений других разработчиков.

Отфильтруйте только до вашего приложения. Для этого справа сверху есть поле поиска. Для этой статьи я сделал приложение LogsDemo, так что именно его и ввожу в поле поиска:

Пусто. Это потому что print() выводит лог напрямую в консоль Xcode, а Console.app пытается читать логи из лог-файлов. Чтобы запись шла в эти самые лог-файлы, нужно print() заменить на os_log(). Apple называет это частью Unified Logging System.

Заменяем, получается так:

let message = "Наше с вами сообщение, которое упадёт в логи"

// вызов os_log требует инстанс OSLog
let osLog = OSLog(subsystem: "LogsDemo", category: "") 

os_log(.debug, // говорим, что уровень лога будет 'debug'
		log: osLog, // передаём тот самый инстанс OSLog
		"%{public}@", message as! CVarArg) // передаём наше сообщение

Запускаем проект и проверяем: в консоль Xcode логи падают, а в Console.app всё ещё нет.

Уровни логов

Логи уровня .debug не складываются в лог-файл, а сразу напрямую улетает в консоль Xcode. Чтобы лог долетел до консоли, достаточно поменять его уровень на любой другой.

Всего уровней пять:

public static let `default`: OSLogType
public static let info: OSLogType
public static let debug: OSLogType
public static let error: OSLogType
public static let fault: OSLogType

Давайте пока укажем .default и проверим:

Всё ещё показываются какие-то системные логи — потому что мы в поле поиска сказали показать любые логи от LogsDemo. По умолчанию это включает в себя и логи от iOS, которые случились в следствие работы нашей приложухи.

Фильтры

Давайте немного уточним фильтр. У нас есть разные варианты:

Все возможные фильтры и ниже варианты их применения. Все возможные фильтры и ниже варианты их применения.

Нам подойдут Library, Equals:

Тестовые логи из демо-приложения. Тестовые логи из демо-приложения.

Наконец-то то, что надо. Но каждый раз вводить в поиске название приложения и уточнять фильтр — лень. Хорошо, что фильтры можно сохранять: прямо под полем поиска есть кнопка Save. Нажимаем, вводим имя для фильтра и он появляется в тулбаре:

Можно сохранять сразу несколько фильтров. Например, у меня есть постоянно живущие фильтры для сетевых запросов и для аналитики внутри Додо Пиццы, а также для своих пет-проектов.

Можно даже фильтр воткнуть только на ошибки. Вызываем контекстное меню лога с ошибкой и просим показать только ошибки:

Контекстное меню у каждой колонки своё. Чтобы получить пункты с фильтрацией по полю Type, нужно кликнуть именно по колонке Type. Контекстное меню у каждой колонки своё. Чтобы получить пункты с фильтрацией по полю Type, нужно кликнуть именно по колонке Type.

И теперь у нас показываются только логи с уровнем .error:

Источник лога

Гораздо чаще при дебаге хочется смотреть не «только ошибки», а логи «только из модуля N». Мы активно пилим приложение Додо Пиццы на модули — их у нас уже 62. Посмотреть только логи из сети — вполне нормальный для нас кейс. В демо-проекте тоже есть модуль Network, давайте отфильтруем логи до него. Но откуда взять название текущего модуля? И куда его передавать? Писать вручную звучит как сложная задача. Да и если файл с кодом между модулями переносить, то можно забыть обновить передаваемое название.

А что если я скажу, что правильное название можно автоматически получить без напряга? Его вернёт выражение #fileID:

let fileID: StaticString = #fileID
// результат — LogsDemo/ViewController.swift

let module = URL(fileURLWithPath: self).deletingPathExtension().pathComponents[1]
// результат — LogsDemo

Теперь в Console.app можно добавить фильтр по Subsystem: Network и увидеть только логи из модуля Network:

Модуль знаем. Что дальше?

Название файла можно достать точно так же, как и название модуля, прямо из #fileID.
Название функции можно достать из #function.
Строчку из #line.

А теперь склеиваем это всё в одно сообщение:

// Раньше в OSLog в поле subsystem мы подавали название приложения
// Но оно и так в любом случае пишется в логи в поле Library
// Так что мы вместо названия приложения теперь подаём название модуля
let osLog = OSLog(subsystem: module, category: "")

let fileFunction = [filename, function].joined(separator: ".")
let source = [fileFunction, line].joined(separator: ":")

let formattedMessage = [source, message].joined(separator: "\n\n")

os_log(.default,
       log: osLog,
       "%{public}@", formattedMessage)

В Console.app так:

Теперь мы знаем, в каком модуле, в каком файле и на какой строчке что произошло. Ну, если залогировали.

А что ещё можно?

Да что угодно — os_log принимает любое текстовое сообщение и выводит его в консоль.

Ошибку? Пожалуйста:

enum TaxCalculationError: Error {
    case invalidTaxConfig
}

let message = String(reflecting: TaxCalculationError.invalidTaxConfig)
os_log(.error,
       log: logger,
       "%{public}@", message)

Замер? Тоже можно:

// логируем старт
let startMessage = "Will get profile"

// специального уровня для замеров нет, так что используем дефолтный
os_log(.default, 
       log: logger,
       "%{public}@", startMessage) 


// запоминаем во сколько мы начали
let startDate = Date()

// выполняем какой-то долгий код
let response = networkService.data(for: ProfileRequest())
let profileModel = ProfileModel(response)

// запоминаем во сколько мы закончили
let endDate = Date()

// сравниваем конечное и стартовое время 
let duration = endDate.timeInterval(since: startDate)
let durationFormatter = String(format: "%.2f", duration)

// логируем конец с продолжительностью
let endMessage = "Got profile, took \(durationFormatter)s"
os_log(.default,
       log: logger,
       "%{public}@", endMessage)

Заключение

Связка os_log и Console.app — мощный инструмент. Вы можете логировать сетевой слой вашего приложения, происходящие в любой момент ошибки, а так же замерить, сколько времени у вас выполнялась та или иная функция и вывести это текстом в логи.

Но для его использования приходится писать много сопроводительного кода. Бойлерплейта, уж простите мне это слово. Надо и обычные сообщения форматировать, и ошибки правильно показывать, и замеры выполнения функций как-то ещё припихнуть. Как этого избежать — расскажу в одной из следующих статей. Подписывайтесь, ставьте лайки, отправляйте эту статью друзьям.