An Analysis of Chromium’s Debug Logging Mechanism

C++ Layer

First, let’s analyze what actually happens when you try to log from within a .so using something like LOG(ERROR) << "Oops! Error";. In base/logging.h, there are definitions for various debug-related macros. From there, we can see the LOG() macro is defined as follows:

:::C++
#define COMPACT_GOOGLE_LOG_EX_ERROR(ClassName, ...) \
  logging::ClassName(__FILE__, __LINE__, logging::LOG_ERROR, ##__VA_ARGS__)
#define COMPACT_GOOGLE_LOG_ERROR \
  COMPACT_GOOGLE_LOG_EX_ERROR(LogMessage)
#define LAZY_STREAM(stream, condition)                 \
!(condition) ? (void) 0 : ::logging::LogMessageVoidify() & (stream)
#define LOG_STREAM(severity) COMPACT_GOOGLE_LOG_ ## severity.stream()
#define LOG_IS_ON(severity) \
  (::logging::ShouldCreateLogMessage(::logging::LOG_##severity))
#define LOG(severity) LAZY_STREAM(LOG_STREAM(severity), LOG_IS_ON(severity))

So, LOG() first invokes LAZY_STREAM(). This macro is just a thin wrapper to ensure that when the logging condition is not satisfied, no evaluation happens at all, avoiding pointless computation. The real control comes from the LOG_STREAM and LOG_IS_ON macros: the former creates a writable stream object, while the latter determines whether anything should actually be written into that stream.

Internally, the LOG_IS_ON macro calls ShouldCreateLogMessage(), which checks a global variable g_min_log_level. This value represents the current global log level. By setting this variable, we can control the effective execution of log statements across all C++ code: for example, if it is set very high, then only logs such as Fatal Error will actually be emitted, while lower-severity logs will be ignored.

Next, let’s look at the LOG_STREAM macro. Through a wrapper layer, it ultimately performs the following call:

logging::ClassName(__FILE__, __LINE__, logging::LOG_ERROR, ##__VA_ARGS__)

Here, ClassName is hard-coded to the LogMessage class. In practice, this simply instantiates a logging::LogMessage object using the current file name, line number, and log severity as parameters. During construction, this object calls its own Init() method, which concatenates a log string prefix based on the constructor parameters and writes it into a std::ostringstream. Finally, this stream is returned as the result of LOG(ERROR), and then your log string can be inserted into that stream.

But now the question is: we constructed a stream and inserted string data, but where does that data go? In principle, if an object is created on the stack and no further action is taken, it will be destructed once it leaves scope. So obviously, processing of the log string is handled in the destructor. Looking at the destructor, it does several things: if a hook function for log messages is defined, it hands the log message to that hook; otherwise, it selects a handling method based on the operating system platform. On Android, it calls __android_log_write, an Android library function, writing the log to logcat with the tag chromium. In addition, if logging to a file is enabled, it will also perform the corresponding file output.

Java Layer

Earlier we mentioned that the global variable g_min_log_level controls whether logs can actually be emitted. So there must be a way to set this value: SetMinLogLevel(). In fact, above this method there is a corresponding Java JNI wrapper, implemented as follows:

:::C++
static jint SetMinLogLevel(JNIEnv* env,
                           const JavaParamRef<jclass>& jcaller,
                           jint jlog_level) {
  jint old_log_level = static_cast<jint>(logging::GetMinLogLevel());
  // MinLogLevel is global, shared by all URLRequestContexts.
  logging::SetMinLogLevel(static_cast<int>(jlog_level));
  return old_log_level;
}

From this we can see that for the cronet library, when the Java application layer starts the app, it calls nativeSetMinLogLevel() to set the global log level. And from the following code, we can see that this log level actually comes from the return value of getLoggingLevel():

:::Java
CronetLibraryLoader.ensureInitialized(builder.getContext(), builder);
nativeSetMinLogLevel(getLoggingLevel());

At this point, we have basically clarified how the Java layer determines the cronet library’s log level: through getLoggingLevel(). Now let’s look at its implementation:

:::Java
private int getLoggingLevel() {
    int loggingLevel;
    if (Log.isLoggable(LOG_TAG, Log.VERBOSE)) {
        loggingLevel = LOG_VERBOSE;
    } else if (Log.isLoggable(LOG_TAG, Log.DEBUG)) {
        loggingLevel = LOG_DEBUG;
    } else {
        loggingLevel = LOG_NONE;
    }
    return loggingLevel;
}

Here we can see that getLoggingLevel() calls Log.isLoggable() (an Android system library function) to read the system-configured log level for a given Log Tag. Based on that configuration, it decides the log level for libcronet.so. In fact, the cronet Java interface defines LOG_TAG = "ChromiumNetwork". Therefore, with the following command, we can lower the system log level for the ChromiumNetwork tag to VERBOSE, and thus successfully print all logs from the cronet library.

adb shell setprop log.tag.ChromiumNetwork VERBOSE

Summary

In summary, if you need to temporarily enable the cronet library’s logging mechanism, you can directly use the adb command above to adjust Android log properties. If instead you want to permanently enable verbose logging and control cronet’s log output yourself in C++ code, you only need to change the default log level in getLoggingLevel() to LOG_VERBOSE.

comments powered by Disqus
Published:
2016-05-20
Category:
Tag: