Как стать автором
Обновить

[boringssl] Failed to log metrics

Время на прочтение7 мин
Количество просмотров5.7K

Наверное, каждый iOS разработчик сталкивался с этой проблемой. Любое приложение, которое делает https запросы, получает в лог эти мистические сообщения от boringssl:

[boringssl] boringssl_metrics_log_metric_block_invoke(151) Failed to log metrics

Минимальный код для воспроизведения проблемы:

URLSession.shared
  .dataTask(with: URL(string: "https://google.com")!)
  .resume()

StackOverflow и другие ресурсы советуют установить переменную окружения OS_ACTIVITY_MODE=disable, но это порождает новую проблему: сообщения из NSLog() так же пропадут из консоли.

// OS_ACTIVITY_MODE=disable

URLSession.shared
  .dataTask(with: URL(string: "https://google.com")!)
  .resume()
NSLog("hello")

// ошибки boringssl пропадут,
// но и "hello" не напечатается

Полное отключение диагностических сообщений через OS_ACTIVITY_MODE=disable никогда не было выходом, так как это делает ситуацию только хуже. Удовлетворив разумное желание избавиться от мусора в логах, взамен мы получаем игнорирование других потенциально важных диагностических сообщений (в том числе своих же NSLog-ов).

Но раз логи нужны и полезны, то зачем тогда что-то отключать?

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

Проблема неотключаемого мусорного логирования от boringssl мучала нас много лет, но, кажется, я нашёл приемлемое решение. Расскажу, как я до него дошёл.

Сперва я хотел понять, где же живёт код, который печатает эти логи. Я решил поискать функции с подстрокой "boringssl" в названии, чтобы узнать, из какой библиотеки или фреймворка они импортируются.

(lldb) image lookup -r -s "boringssl"
13 symbols match the regular expression 'boringssl' in /Applications/Xcode.app/Contents/Developer/Platforms/iPhoneOS.platform/Library/Developer/CoreSimulator/Profiles/Runtimes/iOS.simruntime/Contents/Resources/RuntimeRoot/usr/lib/libnetwork.dylib:
        Address: libnetwork.dylib[0x0000000000090a78] (libnetwork.dylib.__TEXT.__text + 586400)
        Summary: libnetwork.dylib`__nw_protocol_get_boringssl_identifier_block_invoke        Address: libnetwork.dylib[0x0000000000090d1c] (libnetwork.dylib.__TEXT.__text + 587076)
        ...

1251 symbols match the regular expression 'boringssl' in /Applications/Xcode.app/Contents/Developer/Platforms/iPhoneOS.platform/Library/Developer/CoreSimulator/Profiles/Runtimes/iOS.simruntime/Contents/Resources/RuntimeRoot/usr/lib/libboringssl.dylib:
        Address: libboringssl.dylib[0x0000000000001dd4] (libboringssl.dylib.__TEXT.__text + 3844)
        Summary: libboringssl.dylib`boringssl_bio_create        Address: libboringssl.dylib[0x0000000000001ea0] (libboringssl.dylib.__TEXT.__text + 4048)
        ...

libboringssl.dylib выглядит подходящим кандидатом для анализа. Я загрузил файл библиотеки в Hopper Disassembler, чтобы найти строковую константу и места её использования.

Строковая константа быстро нашлась, и используя "References To..." я сразу же нашёл функцию, которая использует эту строку – boringssl_metrics_log_event.

Не являясь экспертом в ассемблере, я переключил Hopper Disassembler в режим "Pseudo Code Mode", и увидел более-менее приличную версию этой функции на Си.

Если убрать всё лишнее, то увидим код:

int boringssl_metrics_log_event(...) {
  // ...
  if (g_boringssl_log != NULL
      && os_log_type_enabled(g_boringssl_log, OS_LOG_TYPE_ERROR))
  {
    os_log_with_type(
      g_boringssl_log, 
      OS_LOG_TYPE_ERROR, 
      "%s(%d) Failed to log metrics",
      "boringssl_metrics_log_metric_block_invoke",
      0x12
    )
  }
  // ...
}

Делаем вывод, что можно отключить логирование внутри boringssl установлением глобальной переменной g_boringssl_log в NULL. Останавливаем исполнение работающей программы, и проверяем доступность переменной в отладчике:

(lldb) p g_boringssl_log
(OS_os_log *) $2 = 0x0000600000ac9d80

Честно говоря, я не совсем понимаю почему эта переменная видна в lldb прямо по имени. Но тем не менее, можно изменить её значение:

(lldb) p g_boringssl_log = 0
(void *) $3 = 0x0000000000000000

Убеждаемся, что после этого логи от boringssl пропадают.

Теперь нужно найти способ автоматически обнулять эту переменную при каждом запуске приложения. Мне сразу пришёл в голову способ с установлением breakpoint, в котором есть action с телом p g_boringssl_log = 0, плюс Automatically continue after evaluating actions.

Однако же, создать такой breakpoint оказалось непросто, так как не совсем очевиден момент во времени, когда этот breakpoint должен сработать. Дело в том, что libboringssl.dylib, судя по всему, загружается динамически, и поставить breakpoint на самый старт приложения (например на main) не получится, т.к. libboringssl ещё не будет загружен, и g_boringssl_log ещё не будет проинициализирована.

Поэтому я стал искать точку инициализации g_boringssl_log.

Снова используя Hopper Disassembler я нашёл символ g_boringssl_log в libboringssl.dylib, и нашёл все его использования. Их оказалось довольно много, так как код проверки на os_log_type_enabled скорее всего оказывается заинлайнен благодаря макросу из <os/log.h>:

#define os_log_with_type(log, type, format, ...) __extension__({ \
    os_log_t _log_tmp = (log); \
    os_log_type_t _type_tmp = (type); \
    if (os_log_type_enabled(_log_tmp, _type_tmp)) { \
        OS_LOG_CALL_WITH_FORMAT(_os_log_impl, \
                (&__dso_handle, _log_tmp, _type_tmp), format, ##__VA_ARGS__); \
    } \
})

#define os_log_error(log, format, ...) \
        os_log_with_type(log, OS_LOG_TYPE_ERROR, format, ##__VA_ARGS__)

Пройдясь по списку функций, использующих эту переменную, я всё же нашёл функцию boringssl_log_open, которая и производит инициализацию g_boringssl_log.

Но был и другой способ найти место инициализации этой переменной: установить watchpoint на её адрес, и отладчик остановится в момент записи нового значения.

Открываем терминал и запускаем lldb отдельно от Xcode:

% lldb

# устанавливаем брейкпоинт на все функции из libboringssl
(lldb) breakpoint set -r '.' -s 'libboringssl.dylib'
Breakpoint 1: no locations (pending).
Breakpoint set in dummy target, will get copied into future targets.

# заставляем отладчик ждать запуска процесса $EXECUTABLE_NAME,
# затем подключиться к процессу, и остановиться
(lldb) process attach -n '$EXECUTABLE_NAME' -w

# после этого вручную запускаем приложение в симуляторе,
# lldb должен подключиться к новому процессу:

Process 25155 stopped
* thread #1, stop reason = signal SIGSTOP
    frame #0: 0x0000000102a58560 dyld`_dyld_start
dyld`_dyld_start:
->  0x102a58560 <+0>:  mov    x0, sp
    0x102a58564 <+4>:  and    sp, x0, #0xfffffffffffffff0
    0x102a58568 <+8>:  mov    x29, #0x0
    0x102a5856c <+12>: mov    x30, #0x0
Target 0: stopped.

Executable module set to "/path/to/executable".
Architecture set to: arm64e-apple-ios-simulator.

# продолжить исполнение до срабатывания breakpoint
# на любой функции из boringssl
(lldb) continue

Process 25155 stopped
* thread #5, queue = 'com.apple.CFNetwork.Connection', stop reason = breakpoint 1.233
    frame #0: 0x0000000185e66c00 libboringssl.dylib`nw_protocol_boringssl_copy_definition
libboringssl.dylib`nw_protocol_boringssl_copy_definition:
->  0x185e66c00 <+0>:  stp    x29, x30, [sp, #-0x10]!
    0x185e66c04 <+4>:  mov    x29, sp
    0x185e66c08 <+8>:  adrp   x8, 337146
    0x185e66c0c <+12>: ldr    x8, [x8, #0xc8]
Target 0: stopped.

# установить watchpoint на адрес g_boringssl_log
(lldb) watchpoint set expression &g_boringssl_log
Watchpoint created: Watchpoint 1: addr = 0x1d8360b28 size = 8 state = enabled type = w
    new value: 0x0000000000000000

# отключить breakpoint, чтобы он больше не срабатывал
(lldb) breakpoint disable 1
1 breakpoints disabled.

# продолжить, чтобы сработал watchpoint
(lldb) continue
Process 25155 resuming

Watchpoint 1 hit:
old value: 0x0000000000000000
new value: 0x0000600000464880
Process 25155 stopped
* thread #5, queue = 'com.apple.CFNetwork.Connection', stop reason = watchpoint 1
    frame #0: 0x0000000185e715dc libboringssl.dylib`__boringssl_log_open_block_invoke + 40
libboringssl.dylib`__boringssl_log_open_block_invoke:
->  0x185e715dc <+40>: mov    x0, x8
    0x185e715e0 <+44>: bl     0x185ee4698               ; symbol stub for: objc_release
    0x185e715e4 <+48>: adrp   x8, 337135
    0x185e715e8 <+52>: ldr    x8, [x8, #0x228]
Target 0: stopped.

Таким образом удалось сразу найти нужную функцию – __boringssl_log_open_block_invoke.

Снова открываем Hopper Disassembler, находим эту функцию и её использования, и
видим следующую картину:

void boringssl_log_open() {
  static dispatch_once_t onceToken;

  dispatch_once(&onceToken, __boringssl_log_open_block_invoke);

  // или в развёрнутом виде:
  dispatch_once(&onceToken, ^{
    g_boringssl_log = os_log_create("com.apple.network", "boringssl");
  });
}

Подумав, я пришёл к выводу, что лучшее, что я могу сделать, это как-то заставить тело dispatch_once перестать выполняться, чтобы g_boringssl_log оставался неинициализированным (NULL).

Такого поведения можно добиться установив breakpoint на __boringssl_log_open_block_invoke и добавив action thread return. Это заставит lldb сразу же выйти из функции, и её тело не будет исполнено.

breakpoint, отключающий вывод логов от boringssl
breakpoint, отключающий вывод логов от boringssl

У логов из boringssl есть "брат", живущий по соседству в libnetwork.dylib, и порождающий сообщения [connection] ... [...] Client called nw_connection_copy_connected_path on unconnected nw_connection.

Эти логи можно отключить тем же способом, добавив такой же брейкпоинт с thread return на ____nwlog_connection_log_block_invoke из libnetwork.dylib.

Напоследок рекомендую создать shared breakpoint и сделать его "глобальным", используя пункт меню "Move Breakpoint to User". Xcode добавит эти брейкпоинты в ~/Library/Developer/Xcode/UserData/xcdebugger/Breakpoints_v2.xcbkptlist, и они автоматически станут видны во всех проектах.

Shared User Breakpoints автоматически добавляются ко всем проектам
Shared User Breakpoints автоматически добавляются ко всем проектам

UPD: как всегда, оказалось, что уже давно есть более человеческий способ заглушить те или иные os_log. Надо было лишь получше поискать.

xcrun simctl spawn booted log config --subsystem com.apple.network --category boringssl --mode "level:off"

Теги:
Хабы:
Всего голосов 13: ↑12 и ↓1+14
Комментарии13

Публикации

Истории

Работа

Swift разработчик
16 вакансий
iOS разработчик
16 вакансий

Ближайшие события

15 – 16 ноября
IT-конференция Merge Skolkovo
Москва
22 – 24 ноября
Хакатон «AgroCode Hack Genetics'24»
Онлайн
28 ноября
Конференция «TechRec: ITHR CAMPUS»
МоскваОнлайн
25 – 26 апреля
IT-конференция Merge Tatarstan 2025
Казань