[IMPALA-7441] Java logging happens before Java logging is configured, leading to INFOs printed at ERROR

• Type: Bug
• Status: Open
• Priority: Trivial
• Resolution: Unresolved
• Component/s: Frontend
• Labels: newbie ramp-up
• Epic Color: ghx-label-3
• Assignee: Unassigned
• Reporter: Philip Martin
• Created: 14/Aug/18 18:01
• Updated: 22/Dec/20 21:10

Description

The following is pretty surprising:

catalogd.....impala.log.ERROR.20180813-040536.9529:18/08/13 04:05:37 INFO util.JvmPauseMonitor: Starting JVM pause monitor

Namely, we've got an INFO-level log message appearing in the ERROR file.

What's going on (I think) is that GlogAppender.Install() is being called during the constructors of Frontend and Catalog objects:

$git grep GlogAppender.Install
fe/src/main/java/org/apache/impala/service/JniCatalog.java:    GlogAppender.Install(TLogLevel.values()[cfg.impala_log_lvl],
fe/src/main/java/org/apache/impala/service/JniFrontend.java:    GlogAppender.Install(TLogLevel.values()[cfg.impala_log_lvl],

Meanwhile, the pause monitor is initialized earlier:

$git grep -C5 JniUtil::InitJvmPauseMonitor | head
be/src/common/init.cc-  if (!fs_cache_init_status.ok()) CLEAN_EXIT_WITH_ERROR(fs_cache_init_status.GetDetail());
be/src/common/init.cc-
be/src/common/init.cc-  if (init_jvm) {
be/src/common/init.cc-    ABORT_IF_ERROR(JniUtil::Init());
be/src/common/init.cc-    InitJvmLoggingSupport();
be/src/common/init.cc:    ABORT_IF_ERROR(JniUtil::InitJvmPauseMonitor());
be/src/common/init.cc-    ZipUtil::InitJvm();
be/src/common/init.cc-  }

This is largely cosmetic, but it was surprising to me.