[boringssl] Failed to log metrics

Наверное, каждый 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 сразу же выйти из функции, и её тело не будет исполнено.

У логов из 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, и они автоматически станут видны во всех проектах.