[boringssl] Failed to log metrics


Probably every iOS developer has faced this problem. Any application that makes https requests gets these mystical messages from boringssl:

[boringssl] boringssl_metrics_log_metric_block_invoke(151) Failed to log metrics

Minimum code to reproduce the problem:

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

StackOverflow and other resources advise setting an environment variable OS_ACTIVITY_MODE=disablebut this creates a new problem: messages from NSLog() will also disappear from the console.

// OS_ACTIVITY_MODE=disable

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

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

Complete disabling of diagnostic messages via OS_ACTIVITY_MODE=disable was never an option as it only makes the situation worse. Having satisfied a reasonable desire to get rid of garbage in the logs, in return we get ignoring other potentially important diagnostic messages (including our own NSLogs).

But since the logs are necessary and useful, then why turn something off?

Spam in the logs seems counterproductive to me. When there are so many logs that you don’t even have time to read the message, then at some point you just stop paying attention to them, and you can miss important messages. Ideally, the log should be empty so that diagnostic messages that suddenly appear are clearly visible, and it is possible to respond to them in time – fix them, and again make the log clean.

The problem of non-disabled garbage logging from boringssl has been tormenting us for many years, but it seems that I found an acceptable solution. I’ll tell you how I got there.

First, I wanted to understand where the code that prints these logs lives. I decided to look for functions with the substring “boringssl” in their name to find out from which library or framework they are imported.

(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 appears to be a suitable candidate for analysis. I loaded the library file into the Hopper Disassembler to find the string constant and where to use it.

The string constant was quickly found, and using “References To…” I immediately found a function that uses this string – boringssl_metrics_log_event.

Not being an expert in assembler, I switched the Hopper Disassembler to “Pseudo Code Mode”, and saw a more or less decent version of this function in C.

If we remove all unnecessary, we will see the code:

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
    )
  }
  // ...
}

We conclude that it is possible to disable logging inside boringssl by setting a global variable g_boringssl_log to NULL. We stop the execution of the running program, and check the availability of the variable in the debugger:

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

To be honest, I don’t quite understand why this variable is visible in lldb right by its name. However, you can change its value:

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

We make sure that after that the logs from boringssl disappear.

Now we need to find a way to automatically reset this variable every time the application starts. I immediately came up with a way to set a breakpoint, in which there is an action with a body p g_boringssl_log = 0plus Automatically continue after evaluating actions.

However, it turned out to be difficult to create such a breakpoint, since the moment in time when this breakpoint should work is not entirely obvious. The fact is that libboringssl.dylibapparently, is loaded dynamically, and put a breakpoint at the very start of the application (for example, on main) will not work, because libboringssl not loaded yet, and g_boringssl_log will not be initialized yet.

So I started looking for an initialization point g_boringssl_log.

Using the Hopper Disassembler again I found the symbol g_boringssl_log in libboringssl.dylib, and found all its uses. There were quite a lot of them, since the verification code for os_log_type_enabled most likely it turns out to be inlined due to the macro from <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__)

Going through the list of functions that use this variable, I still found a function boringssl_log_openwhich performs the initialization g_boringssl_log.

But there was another way to find the place of initialization of this variable: set a watchpoint to its address, and the debugger would stop at the moment the new value was written.

Open terminal and run lldb apart from 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.

Thus, it was possible to immediately find the desired function – __boringssl_log_open_block_invoke.

Open the Hopper Disassembler again, find this function and its uses, and
we see the following picture:

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");
  });
}

On reflection, I came to the conclusion that the best thing I can do is somehow force the body dispatch_once stop running to g_boringssl_log remained uninitialized (NULL).

This behavior can be achieved by setting a breakpoint to __boringssl_log_open_block_invoke and adding action thread return. This will cause lldb to exit the function immediately and its body will not be executed.

breakpoint to disable logging from boringssl
breakpoint to disable logging from boringssl

Boringssl logs have a “brother” living next door in libnetwork.dyliband generating messages [connection] ... [...] Client called nw_connection_copy_connected_path on unconnected nw_connection.

These logs can be disabled in the same way by adding the same breakpoint with thread return on the ____nwlog_connection_log_block_invoke from libnetwork.dylib.

Finally, I recommend creating a shared breakpoint and making it “global” using the “Move Breakpoint to User” menu item. Xcode will add these breakpoints to ~/Library/Developer/Xcode/UserData/xcdebugger/Breakpoints_v2.xcbkptlistand they will automatically become visible in all projects.

Shared User Breakpoints are automatically added to all projects
Shared User Breakpoints are automatically added to all projects

Similar Posts

Leave a Reply

Your email address will not be published. Required fields are marked *