Логи в iOS, эпизод 3: BlackBox30.12.2022 15:01

В 2019 году я устроился в Додо Пиццу. В первую же неделю я спросил у ребят, как они логируют происходящее в iOS-приложении у клиентов и узнал, что никак.

Я удивился и понял, что у меня нет абсолютно никакой уверенности, что приложение Додо Пиццы работает как было задумано. А ещё мне очень интересно было, как логируют «большие взрослые дяди»: перед Додо я работал над небольшими проектами, где было не до логов, так что опыта у меня не было.

Итого: клиентских логов нет, а неопределённость и интерес остались. Значит, надо сделать систему логов самому. Ну, я и сделал. А это — история появления и развития логов в iOS-приложении Додо Пиццы.

Глава 1. Сумерки. os_log.

Сели с Мишей Рубановым думать, с чего начать. То ли нагуглили, то ли вспомнили про os_log. Решили начать его использовать в проекте.

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

К сожалению, мы очень быстро столкнулись с проблемой: нужно писать много сопроводительного кода. Для простого лога по типу App Launched нужно написать вот такую конструкцию:

let message = "App Launched"
let osLog = OSLog(subsystem: "DodoPizza", category: "App Lifecycle") 
os_log(.debug,
       log: osLog,\
       "%{public}@", message)

И так постоянно: из класса в класс, из функции в функцию. Надо что-то делать.

Глава 2. Новолуние. BlackBox.

Решили вынести весь бойлерплейт в отдельный сервис. Назвали его BlackBox — как бортовой черный ящик.

Простые текстовые сообщения

Работает просто: мы ему сообщение, а он там пусть внутри себя разруливает всё что надо. Как итог — логи упростились до такого вызова:

BlackBox.log("App Launched")

BlackBox на это сообщение создаёт OSLog, вызывает os_log и подставляет в него наше сообщение.

В коде приложения автозаменой все print заменили на BlackBox.log. Теперь внутри этого враппера можно менять код как нам надо, а основное приложение не трогать. Хорошая стартовая точка.

Уровни логов

Чтобы в Console.app стало удобно ориентироваться в логах — передаём вместе с сообщением уровень:

BlackBox.log("User Did Finish Auth", level: .info)

BlackBox этот уровень просто передаёт в os_log рядом с сообщением.

Сопроводительная информация

Очень скоро захотелось вместе с сообщением передавать какие-то полезности. Например не просто писать, что кинули запрос в сеть, а ещё и на какой URL. И какой ответ от сети в итоге получили. Делаем:

BlackBox.log("Start Request", userInfo: ["url": request.url])

BlackBox эту информацию форматирует и подмешивает в сообщение.

Вы спросите:, а мы не могли сразу сами в сообщение эту инфу подмешать? Могли, но:

Сообщение станет «сложно» выглядеть.
Логика форматирования сообщения начнёт жить в файлах, откуда логируем. А мы наоборот увозим код по максимуму в BlackBox.
Ещё одна секретная причина.

Ошибки

Со временем мы захотели логировать не только обычные текстовые сообщения, но и ошибки. Можно просто начать передавать уровень .error вместе с сообщением, примерно так:

BlackBox.log("Failed to load image", level: .error)

Но с таким решением есть проблема: это можно легко забыть. А ещё если мы в каком-то месте в коде словили объект Swift.Error, то почему мы не логируем его напрямую, а заменяем его на какое-то другое сообщение?

Расширяем API BlackBox и учим его принимать не только текстовые сообщения, но объекты Swift.Error. В коде начинает выглядеть так:

catch let error {
    BlackBox.log(error)
}

BlackBox эту ошибку превращает в сообщение.

При этом в метод логирования ошибки мы принципиально не добавляем сопроводительную информацию — userInfo. Если она есть и важна — она должна быть прямо в самой ошибке. Чтобы её туда вогнать нужно реализовать CustomNSError:

enum NetworkError: Error, CustomNSError {
    // добавляем интересующую нам инфу в саму ошибку
    case networkRequestFailed(_ request: String) 

    // собираем для каждого кейса словарь из прикопанных значений
    var errorUserInfo: [String : Any] { 
        switch self {
        case .networkRequestFailed(let request):
            return ["request": request]
        }
    }
}

BlackBox в методе логирования ошибки эту информацию вытаскивает и подмешивает в сообщение.

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

В какой-то момент логов стало много и захотелось их фильтровать по модулям или даже по файлам. Для этого пользуемся выражениями #fileID, #function и #line.

Самое прикольное, что мы один раз прописали это в методах логирования в BlackBox и все вызовы BlackBox.log() сразу стали поставлять эту информацию.

Если не знаете, как эти выражения работают

Всё просто — в той функции, где хотим узнать источник вызова, добавляем 3 новых аргумента и проставляем им эти выражения как значения по умолчанию:

func buttonTapped() {
    log("User Did Tap Button")
}

func log(_ message: String,
         fileID: StaticString = #fileID,
         function: StaticString = #function,
         line: UInt = #line) {
    // здесь мы получаем не только сообщение,
    // но и название модуля и файла, откуда была вызвана функция log — в fileID
    // название функции — в function
    // номер строчки — в line
}

Замеры

Потом мы захотели замерять как долго наш код работает.

Конечно, можно в каждом нужном месте заново реализовывать логику замеров создавая две даты, сравнивая их, форматируя разницу и выводя её в логи обычным текстовым сообщением. Но опять же: мы стараемся весь бойлерплейт увезти внутрь BlackBox.

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

let log = BlackBox.logStart("Make Request")
let response = network.getResponse(for: request)
BlackBox.logEnd(log)

BlackBox сам считает длительность замеров и подмешивает её в сообщение.

Почему не сделали замер через замыкание?

На самом деле мы рассматривали такой вариант для API замеров:

BlackBox.measure("Make Request") {
    let response = network.getResponse(for: request)
}

Но решили не делать по нескольким причинам:

Влияет на выравнивание кода.
Нельзя начать лог в одном методе и закончить в другом.
Нельзя замерить другие замыкания.

Для решения этой задачи нам пришлось ввести сущность лога. Причем сделали это не только для замеров, а сразу для всех логов:

GenericEvent — обычный тестовый лог.
ErrorEvent — лог с ошибкой.
StartEvent — лог старта замера.
EndEvent — лог окончания замера.

Где-то тут вы можете спросить «Лёха, ты че, поехал?». Не волнуйтесь, я не перегибаю палку. Отдельные сущности для каждого лога нам очень сильно пригодятся, но чуть позже.

По итогу в логах видно:

Приложение.
Модуль.
Файл.
Функцию.
Строчку.
Текст или описание ошибки.
Замеры продолжительности.
Сопроводительную инфу.

Выигрышей после всех этих дел несколько:

В основном приложении стало чище, так как мы увезли весь код по форматированию и отправке сообщений в os_log внутрь BlackBox.
Форматирование у всех сообщений одинаковое.
Низкий порог вхождения, чтобы отправить лог в Console.app.

На этом os_log оставляем в покое и заканчиваем вступление статьи.

Глава 3. Затмение. Плагины.

Так получилось, что BlackBox взял на себя две ответственности:

Принять вызов log(), сформировать из него какой-либо Event и передать его в метод логирования в os_log.
В методе логирования в os_log принять готовый ивент и правильно из него сформировать сообщение.

Мы разбили это дело на две разных сущности: BlackBox и OSLogger.

Получается, что:

BlackBox будет только:
1. Принимать логи.
2. Формировать из них Event«ы.
3. Передавать их новой сущности — OSLogger'у.
OSLogger же будет:
1. Принимать Event«ы.
2. Делать всё необходимое форматирование.
3. Отдавать правильно отформатированное сообщение в os_log, чтобы оно появилось в Console.app.

Для ясности (надеюсь) вот схема:

Приложение логирует инфу. BlackBox формирует из инфы Event и передаёт в OSLogger. OSLogger форматирует из ивента сообщение и передаёт в os_log.

Смотреть логи в Console.app удобно, но это всё ещё не даёт никакого понимания что происходит у клиентов. А ведь это и было исходной целью всей затеи.

Мы уже выделили OSLogger в отдельный файл. Но чтобы BlackBox легко работал и с другими логгерами нужно всех их скрыть за протоколом. Мы создали LoggerProtocol:

protocol LoggerProtocol {
    func log(_ event: GenericEvent)
}

А затем загнали под этот протокол наш OSLogger и научили BlackBox работать не с одним, а с коллекцией логгеров.

Так мы смогли создавать и добавлять в BlackBox новые логгеры. Начали с CrashlyticsLogger.

CrashlyticsLogger

import FirebaseCrashlytics

class CrashlyticsLogger: LoggerProtocol {
    func log(_ event: GenericEvent) {
		guard let errorEvent = event as? ErrorEvent else { else return } 
        Crashlytics.crashlytics().record(error: errorEvent.error)
    }
}

Пара строчек кода и все наши ошибки, которые мы логировали через BlackBox, стали перенаправляться ещё и в Crashlytics. Маленький ченж для кода, но большой — для приложения.

Давайте проверим, как в Crashlytics всё показывается:

Всё как с крашами, только помечается как Non-fatal.

Нолик под название ошибки — это код ошибки. Его можно закастомизировать, если реализовать протокол CustomNSError и переопределить метод errorCode:

enum NetworkError: Error, CustomNSError {
    case networkRequestFailed

    var errorCode: Int {
        switch self {
        case .networkRequestFailed:
            return 4000 // или любой другой код, который вам нравится
        }
    }
}

А ещё в Crashlytics можно точно так же открыть каждую нашу ошибку, увидеть стак-трейс и даже наши прикрепленные данные из errorUserInfo:

Это та самая «ещё одна секретная причина», почему сопроводительную информацию не надо подмешивать прямо в сообщение: некоторым логерам она нужна в сыром виде, чтобы они могли делать с ней разные вещи.

OSSignpostLogger

Ранее мы добавили в логи замеры. Например, как долго шли сетевые запросы. Читать их в Console.app хорошо, но не хватает визуальности.

В предыдущей статье я показал как можно смотреть наши логи в Time Profiler. Но там же я пришёл к выводу, что для этого приходится писать много сопровождающего кода. Что ж, теперь мы можем описать его единожды, в специальном логгере. Погнали, всё как с предыдущими логгерами:

Создали OSSignpostLogger.
Реализовали у него LoggerProtocol.
Научили правильно форматировать сообщения и передавать их в os_signpost.
Добавили этот логгер в BlackBox.

И снова ловим кайфы: все замеры, которые мы делали через BlackBox, теперь ещё и в Time Profiler прилетают:

FirebasePerformanceLogger

Снимать замеры и смотреть их в Time Profiler в момент разработки — хорошо. Но это слабо отражает то, что происходит у реальных пользователей на проде.

В Crashlytics ошибки мы отправлять научились. Давайте теперь попробуем перенаправить замеры в Firebase Performace. Так мы сможем получать настоящие замеры от реальных пользователей.

Погнали, всё как с предыдущими логгерами:

Создали FirebasePerformanceLogger.
Реализовали у него LoggerProtocol.
Научили правильно форматировать сообщения и передавать их в Firebase Performance.
Добавили этот логгер в BlackBox.

Открываем Firebase Performance и кайфуем — все наши замеры уже там:

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

Кстати, в FirebasePerformanceLogger мы в ивенты подмешиваем сопроводительную информацию из userInfo. Это позволяет в трейсах увидеть причины проблем.
Пример:

Добавляем в трейс скачки картинок источник запроса: Меню или Корзина.
Смотрим на метрики и понимаем, что в меню картинки почему-то скачиваются дольше, хотя не должны.
Дебажим и узнаём, что мы запрашиваем их большего размера, чем должны.

Любой другой логгер

Наша лог-система готова принять в себя любой логгер:

Пишущий в текстовый файл.
Отправляющий в любой сторонний лог-сервис.
Показывающий случившиеся в дебажной сборке ошибки баннерами прямо поверх приложения.
Вообще. Любой. Другой.

Глава 4. Рассвет. Open Source.

Нашу лог-систему мы решили выложить в открытый доступ. Вместе с ней и несколько логгеров:

BlackBox
1. OSLogger
2. OSSignpostLogger
CrashlyticsLogger
FirebasePerformanceLogger

Интегрируйте в свои проекты, рассказывайте об успехах — очень интересно.

Заключение

Логи помогают в сложных кейсах разобраться в чем же причина странного поведения приложения. Логи помогают найти баги, а так же проблемы с производительностью приложения. Логи дают больше уверенности, что всё работает как надо и отлично дополняют аналитику.

Если меня спросят как мы логируем происходящее в iOS-приложении у клиентов я с гордостью отвечу: «Ой, вы не поверите» и скину ссылку на эту статью.