Impala的log4j和glog配置

背景

Impala server的代码由C++和Java两部分组成，C++日志使用glog，Java日志使用log4j。这两部分输出是如何汇聚到同一个日志文件里的呢？日志级别又是如何协调配置的呢？

之前在开发Impala的过程中，总发现一些加在构造函数里的日志没被打印出来，比如JniCatalog。最近终于弄清了impala的日志是怎么配置的，在此梳理一下。

日志初始化入口

/// Initialises logging, flags, and, if init_jvm is true, an embedded JVM.
/// Tests must indicate if they are a FE or BE test to output logs to the appropriate
/// logging directory, and enable special test-specific behavior.
/// Callers that want to override default gflags variables should do so before calling
/// this method. No logging should be performed until after this method returns.
/// Passing external_fe=true causes specific initialization steps to be skipped
/// that an external frontend will have already performed.
void InitCommonRuntime(int argc, char** argv, bool init_jvm,
    TestInfo::Mode m = TestInfo::NON_TEST, bool external_fe = false);
1
2
3
4
5
6
7
8
9

正如注释所说，这个函数会初始化日志和JVM（在impalad和catalogd的调用里，init_jvm都是true）。有了JVM之后才会初始化log4j，因此impala server里是先初始化 glog，再初始化 log4j。但在FE单元测试里就不一样了，FE单元测试是maven启动的，已经有JVM了，因此log4j也已经初始化完成了。有些FE单元测试会初始化FeSupport，以调用C++代码，这时才会初始化glog。

glog初始化

InitCommonRuntime() 调用 InitGoogleLoggingSafe(const char* arg) 来初始化 glog，这个函数接收一个字符串作为参数，传入时用的是 argv[0]，即可执行文件名，比如impalad、catalogd这样的。主要内容是：

  google::InitGoogleLogging(arg);
  google::InstallLogMessageListenerFunction(MessageListener);
1
2

其它都是一些检查性质的，比如检查日志目录是否有权限能创建日志文件。这里的 MessageListener 主要做两件事，redact（脱敏）和增加 fragment id 。

// Manipulates log messages by:
// - Applying redaction rules (if necessary)
// - Prepending fragment id (if available)
void MessageListener(string* s, bool* changed) {
  if (!FLAGS_redaction_rules_file.empty()) {
    impala::Redact(s, changed);
  }
  PrependFragment(s, changed);
}
1
2
3
4
5
6
7
8
9

Log4j配置

常见的Log4j配置方式是使用log4j.properties或log4j.xml配置文件，这样不用写死代码。但Impala目前是用代码的方式来配置，大概是为了统一用gflag来操作。具体代码入口在org.apache.impala.util.GlogAppender#Install()

  public static void Install(TLogLevel impalaLogLevel, TLogLevel otherLogLevel)
      throws InternalException {
    Properties properties = new Properties();
    properties.setProperty("log4j.appender.glog", GlogAppender.class.getName());
    // ...
    properties.setProperty("log4j.rootLogger",
        log4jLevelForTLogLevel(otherLogLevel) + ",glog");
    properties.setProperty("log4j.appender.glog.Threshold", "TRACE");
    properties.setProperty("log4j.logger.org.apache.impala",
        log4jLevelForTLogLevel(impalaLogLevel));
    PropertyConfigurator.configure(properties);
    Logger.getLogger(GlogAppender.class).info(String.format("Logging (re)initialized. " +
        "Impala: %s, All other: %s", impalaLogLevel, otherLogLevel));
  }
1
2
3
4
5
6
7
8
9
10
11
12
13
14

这里定义了一个叫glog的appender，代码实现是GlogAppender。然后把rootLogger配到glog这个appender。日志级别有两个，一个是全局的（otherLogLevel），另一个是只针对 org.apache.impala 包级别的（impalaLogLevel）。

看看这个函数是怎么被调用的，在JniCatalog.java和JniFrontend.java的构造函数里，都有这样的代码：

// This trick saves having to pass a TLogLevel enum, which is an object and more
// complex to pass through JNI.
GlogAppender.Install(TLogLevel.values()[cfg.impala_log_lvl],
    TLogLevel.values()[cfg.non_impala_java_vlog]);
1
2
3
4

所以如果在这行代码前打日志，则日志不会输出到INFO文件里。

注：cfg.impala_log_lvl和cfg.non_impala_java_vlog的值在 be/src/util/backend-gflag-util.cc 中初始化：

cfg.__set_impala_log_lvl(FlagToTLogLevel(FLAGS_v)); 
cfg.__set_non_impala_java_vlog(FlagToTLogLevel(FLAGS_non_impala_java_vlog));
1
2

这对应 -v 和 -non_impala_java_vlog 两个启动参数。FlagToTLogLevel() 定义在 be/src/util/logging-support.cc 中（省略）

GlogAppender 实现

GlogAppender主要实现append()接口：

  @Override
  public void append(LoggingEvent event) {
    Level level = event.getLevel();
    if (level.equals(Level.OFF)) return;

    String msg = event.getRenderedMessage();
    if (event.getThrowableInformation() != null) {
      msg = msg + "\nJava exception follows:\n" +
          Joiner.on("\n").join(event.getThrowableStrRep());
    }
    int lineNumber = Integer.parseInt(event.getLocationInformation().getLineNumber());
    String fileName = event.getLocationInformation().getFileName();
    NativeLogger.LogToGlog(
        levelToSeverity(level).getValue(), msg, fileName, lineNumber);
  }
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15

这里会把Java的Exception信息整合进日志内容里，然后调用NativeLogger.LogToGlog()传给glog。NativeLogger的代码很简单：

/**
 * Class that manages loading and calling the native logging library to forward
 * log4j log messages to be logged by glog.
 */
public class NativeLogger {
  private static boolean loaded_ = false;

  // Writes a log message to glog
  private native static void Log(int severity, String msg, String filename, int line);

  public static void LogToGlog(int severity, String msg, String filename, int line) {
    try {
      Log(severity, msg, filename, line);
    } catch (UnsatisfiedLinkError e) {
      loadLibrary();
      Log(severity, msg, filename, line);
    }
  }

  /**
   * Loads the native logging support library.
   */
  private static synchronized void loadLibrary() {
    if (loaded_) return;
    NativeLibUtil.loadLibrary("libloggingsupport.so");
    loaded_ = true;
  }
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28

Log()函数通过JNI会调用C++的实现，如果找不到（即UnsatisfiedLinkError），会再动态加载 libloggingsupport.so。目前的Impala默认使用静态链接来编译，因此发布时不再需要带上这个so文件。

NativeLogger#Log() 实现

见be/src/util/logging-support.cc，主要是最后一行:

// Requires JniUtil::Init() to have been called. Called by the frontend and catalog
// service to log messages to Glog.
extern "C"
JNIEXPORT void JNICALL
Java_org_apache_impala_util_NativeLogger_Log(
    JNIEnv* env, jclass caller_class, int severity, jstring msg, jstring file,
    int line_number) {
  ...
  google::LogMessage(filename_guard.get(), line_number, log_level).stream() << str;
}
1
2
3
4
5
6
7
8
9
10

这个JNI函数是在InitJvmLoggingSupport()注册的，见be/src/util/logging-support.cc：

void InitJvmLoggingSupport() {
  JNIEnv* env = JniUtil::GetJNIEnv();
  JNINativeMethod nm;
  jclass native_backend_cl = env->FindClass("org/apache/impala/util/NativeLogger");
  nm.name = const_cast<char*>("Log");
  nm.signature = const_cast<char*>("(ILjava/lang/String;Ljava/lang/String;I)V");
  nm.fnPtr = reinterpret_cast<void*>(::Java_org_apache_impala_util_NativeLogger_Log);
  env->RegisterNatives(native_backend_cl, &nm, 1);
  ABORT_IF_EXC(env);
  InitDynamicLoggingSupport();
}
1
2
3
4
5
6
7
8
9
10
11

最后的InitDynamicLoggingSupport()也初始化了动态调整日志级别的几个函数：getLogLevels、setLogLevel、resetLogLevels。

InitJvmLoggingSupport() 就是在 InitCommonRuntime() 里被调用的（当init_jvm=true时）

Impala服务的日志初始化流程

ImpaladMain 里的流程如下：

InitCommonRuntime(argc, argv, true)
--> InitGoogleLoggingSafe(argv[0]) // init glog
--> JniUtil::Init()
--> InitJvmLoggingSupport()
ExecEnv()
--> Frontend()
    --> JniFrontend()
        --> GlogAppender.Install()    // init log4j
1
2
3
4
5
6
7
8

CatalogdMain 里的流程如下：

InitCommonRuntime(argc, argv, true) // init glog
--> 同上
CatalogServer::Start()
--> Catalog()
    --> JniCatalog()
        --> GlogAppender.Install()    // init log4j
1
2
3
4
5
6

StatestoredMain 只调用 InitCommonRuntime()，略。

FE测试日志初始化流程

许多FE测试会继承FrontendTestBase，从而继承AbstractFrontendTest。这些在构造函数里就会初始化日志，调用堆栈比较复杂，首先是进入FeSupport.NativeFeInit：

 at org.apache.impala.service.FeSupport.NativeFeInit(Native Method)
 at org.apache.impala.service.FeSupport.loadLibrary(FeSupport.java:494)
 at org.apache.impala.service.FeSupport.LookupSymbol(FeSupport.java:213)
 at org.apache.impala.service.FeSupport.LookupSymbol(FeSupport.java:222)
 at org.apache.impala.catalog.Function.lookupSymbol(Function.java:475)
 at org.apache.impala.catalog.ScalarFunction.createBuiltin(ScalarFunction.java:184)
 at org.apache.impala.catalog.ScalarFunction.createBuiltinOperator(ScalarFunction.java:172)
 at org.apache.impala.catalog.ScalarFunction.createBuiltinOperator(ScalarFunction.java:167)
 at org.apache.impala.analysis.ArithmeticExpr.initBuiltins(ArithmeticExpr.java:105)
 at org.apache.impala.catalog.BuiltinsDb.initBuiltins(BuiltinsDb.java:105)
 at org.apache.impala.catalog.BuiltinsDb.(BuiltinsDb.java:94)
 at org.apache.impala.catalog.BuiltinsDb.getInstance(BuiltinsDb.java:79)
 at org.apache.impala.catalog.ImpaladCatalog.(ImpaladCatalog.java:113)
 at org.apache.impala.testutil.ImpaladTestCatalog.(ImpaladTestCatalog.java:58)
 at org.apache.impala.testutil.ImpaladTestCatalog.(ImpaladTestCatalog.java:51)
 at org.apache.impala.common.FrontendFixture.(FrontendFixture.java:101)
 at org.apache.impala.common.FrontendFixture.(FrontendFixture.java:94)
 at org.apache.impala.common.AbstractFrontendTest.(AbstractFrontendTest.java:42)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18

这是个JNI函数，调用了C++代码，见 be/src/service/fe-support.cc：

// Called from tests or external FE after it explicitly loads libfesupport.so.
// This creates the minimal state necessary to service the other JNI calls.
// This is not called when we first start up the BE.
extern "C"
JNIEXPORT void JNICALL
Java_org_apache_impala_service_FeSupport_NativeFeInit(
    JNIEnv* env, jclass fe_support_class, bool external_fe) {
  DCHECK(ExecEnv::GetInstance() == NULL) << "This should only be called once from the FE";
  char* env_logs_dir_str = std::getenv("IMPALA_FE_TEST_LOGS_DIR");
  if (env_logs_dir_str != nullptr) FLAGS_log_dir = env_logs_dir_str;
  char* name = const_cast<char*>("FeSupport");
  // Init the JVM to load the classes in JniUtil that are needed for returning
  // exceptions to the FE.
  InitCommonRuntime(1, &name, true,
      external_fe ? TestInfo::NON_TEST : TestInfo::FE_TEST, external_fe);
  THROW_IF_ERROR(LlvmCodeGen::InitializeLlvm(true), env, JniUtil::internal_exc_class());
  ExecEnv* exec_env = new ExecEnv(external_fe); // This also caches it from the process.
  THROW_IF_ERROR(exec_env->InitForFeSupport(), env, JniUtil::internal_exc_class());
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19

这里首先配置日志目录为 $IMPALA_FE_TEST_LOGS_DIR，默认是 $IMPALA_HOME/logs/fe_tests。

然后使用 FeSupport 的名字调用 InitCommonRuntime() 来初始化 glog，日志文件名就是 FeSupport.INFO、FeSupport.ERROR 这样的形式。

最后生成一个ExecEnv对象，这个构造函数最终会再配置 log4j（同impalad）：

ExecEnv()
--> Frontend()
    --> JniFrontend()
        --> GlogAppender.Install()    // init log4j
1
2
3
4

值得一提的是，FE测试是maven启动的，JVM已经初始化好了，log4j也已经开始运行一阵子了，到这里只是重新配置了 log4j，把输出重定向到 glog 里。在这之前的日志都按 log4j 默认的方式打到了标准输出，从而被 maven-surefire-plugin 重定向到 org.apache.impala.xxxTest-output.txt 这样的日志文件里。

注：不继承FrontendTestBase的FE test则没有初始化glog，所有日志打到logs/fe_tests/org.apache.impala.xxxTest-output.txt 文件

相关启动参数

-v 配置glog日志级别（0、1、2、3），越大越详细。同时也会配置log4j里org.apache.impala包的日志级别。
-non_impala_java_vlog 配置log4j里非impala类的日志级别

日志级别对应表

glog -v --> TLogLevel

TLogLevel --> Log4j

Log4j --> TLogLevel