[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 скорее всего оказывается заинлайнен благодаря макросу из
#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
У логов из 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 автоматически добавляются ко всем проектам
