[opt](log) refine the BE logger (apache#35942)

Followup apache#35679 ## Background Previously, BE logs were written to files. The main FE logs include be.INFO, be.WARNING, be.out, be.gc.log and jni.log. In a K8s deployment environment, logs usually need to be output to standard output, and then other components process the log stream. ## Solution This PR made the following changes: 1. Modified the glog config: - When started with `--daemon`, logs are still written to various files, and the format remains unchanged. - When started with `--console`, be.INFO's log is output to standard output and marked with prefix `RuntimeLogger`. Examples are as follows: ``` RuntimeLogger I20240605 23:41:20.426553 4137369 runtime_query_statistics_mgr.cpp:245] Report profile thread stopped ``` 2. Added a new BE config: `enable_file_logger` Defaults to true. Indicates that logs will be recorded to files regardless of the startup method. For example, if it is started with `--console`, the log will be output to both the file and the standard output. If it is `false`, the log will not be recorded in the file regardless of the startup method. ## TODO - Need to handle jni.log in next PR
xiedeyantu · Jun 6, 2024 · 6cd0669 · 6cd0669
1 parent 0858dc8
commit 6cd0669
Show file tree

Hide file tree

Showing 6 changed files with 81 additions and 26 deletions.
diff --git a/be/CMakeLists.txt b/be/CMakeLists.txt
@@ -66,6 +66,9 @@ else()
     add_definitions(-DBOOST_STACKTRACE_USE_NOOP)
 endif()
 
+# enable glog custom prefix
+add_definitions(-DGLOG_CUSTOM_PREFIX_SUPPORT)
+
 # Options
 option(GLIBC_COMPATIBILITY "Enable compatibility with older glibc libraries." ON)
 option(USE_LIBCPP "Use libc++" OFF)

diff --git a/be/src/common/config.cpp b/be/src/common/config.cpp
@@ -1292,6 +1292,8 @@ DEFINE_Bool(enable_jvm_monitor, "false");
 // Skip loading stale rowset meta when initializing `TabletMeta` from protobuf
 DEFINE_mBool(skip_loading_stale_rowset_meta, "false");
 
+DEFINE_Bool(enable_file_logger, "true");
+
 // clang-format off
 #ifdef BE_TEST
 // test s3

diff --git a/be/src/common/config.h b/be/src/common/config.h
@@ -1369,6 +1369,11 @@ DECLARE_Bool(enable_jvm_monitor);
 
 // Skip loading stale rowset meta when initializing `TabletMeta` from protobuf
 DECLARE_mBool(skip_loading_stale_rowset_meta);
+// Whether to use file to record log. When starting BE with --console,
+// all logs will be written to both standard output and file.
+// Disable this option will no longer use file to record log.
+// Only works when starting BE with --console.
+DECLARE_Bool(enable_file_logger);
 
 #ifdef BE_TEST
 // test s3

diff --git a/be/src/common/logconfig.cpp b/be/src/common/logconfig.cpp
@@ -21,6 +21,7 @@
 #include <cerrno>
 #include <cstdlib>
 #include <cstring>
+#include <iomanip>
 #include <iostream>
 #include <mutex>
 #include <string>
@@ -48,15 +49,42 @@ static bool iequals(const std::string& a, const std::string& b) {
     return true;
 }
 
+void custom_prefix(std::ostream& s, const google::LogMessageInfo& l, void*) {
+    // Add prefix "RuntimeLogger ".
+    s << "RuntimeLogger ";
+    // Same as in fe.log
+    // The following is same as default log format. eg:
+    // I20240605 15:25:15.677153 1763151 wal_manager.cpp:481] msg...
+    s << l.severity[0];
+    s << std::setw(4) << 1900 + l.time.year();
+    s << std::setw(2) << 1 + l.time.month();
+    s << std::setw(2) << l.time.day();
+    s << ' ';
+    s << std::setw(2) << l.time.hour() << ':';
+    s << std::setw(2) << l.time.min() << ':';
+    s << std::setw(2) << l.time.sec() << ".";
+    s << std::setw(6) << l.time.usec();
+    s << ' ';
+    s << std::setfill(' ') << std::setw(5);
+    s << l.thread_id << std::setfill('0');
+    s << ' ';
+    s << l.filename << ':' << l.line_number << "]";
+}
+
 bool init_glog(const char* basename) {
     std::lock_guard<std::mutex> logging_lock(logging_mutex);
 
     if (logging_initialized) {
         return true;
     }
 
-    if (getenv("DORIS_LOG_TO_STDERR") != nullptr) {
-        FLAGS_alsologtostderr = true;
+    bool log_to_console = (getenv("DORIS_LOG_TO_STDERR") != nullptr);
+    if (log_to_console) {
+        if (config::enable_file_logger) {
+            FLAGS_alsologtostderr = true;
+        } else {
+            FLAGS_logtostderr = true;
+        }
     }
 
     // don't log to stderr except fatal level
@@ -144,7 +172,12 @@ bool init_glog(const char* basename) {
         }
     }
 
-    google::InitGoogleLogging(basename);
+    if (log_to_console) {
+        // Only add prefix if log output to stderr
+        google::InitGoogleLogging(basename, &custom_prefix);
+    } else {
+        google::InitGoogleLogging(basename);
+    }
 
     logging_initialized = true;
 

diff --git a/bin/start_be.sh b/bin/start_be.sh
@@ -81,17 +81,41 @@ PID_DIR="$(
 )"
 export PID_DIR
 
+# read from be.conf
+while read -r line; do
+    envline="$(echo "${line}" |
+        sed 's/[[:blank:]]*=[[:blank:]]*/=/g' |
+        sed 's/^[[:blank:]]*//g' |
+        grep -E "^[[:upper:]]([[:upper:]]|_|[[:digit:]])*=" ||
+        true)"
+    envline="$(eval "echo ${envline}")"
+    if [[ "${envline}" == *"="* ]]; then
+        eval 'export "${envline}"'
+    fi
+done <"${DORIS_HOME}/conf/be.conf"
+
+STDOUT_LOGGER="${LOG_DIR}/be.out"
+log() {
+    # same datetime format as in fe.log: 2024-06-03 14:54:41,478
+    cur_date=$(date +"%Y-%m-%d %H:%M:%S,$(date +%3N)")
+    if [[ "${RUN_CONSOLE}" -eq 1 ]]; then
+        echo "StdoutLogger ${cur_date} $1"
+    else
+        echo "StdoutLogger ${cur_date} $1" >>"${STDOUT_LOGGER}"
+    fi
+}
+
 jdk_version() {
     local java_cmd="${1}"
     local result
     local IFS=$'\n'
 
     if ! command -v "${java_cmd}" >/dev/null; then
-        echo "ERROR: invalid java_cmd ${java_cmd}" >>"${LOG_DIR}/be.out"
+        echo "ERROR: invalid java_cmd ${java_cmd}" >>"${STDOUT_LOGGER}"
         result=no_java
         return 1
     else
-        echo "INFO: java_cmd ${java_cmd}" >>"${LOG_DIR}/be.out"
+        echo "INFO: java_cmd ${java_cmd}" >>"${STDOUT_LOGGER}"
         local version
         # remove \r for Cygwin
         version="$("${java_cmd}" -Xms32M -Xmx32M -version 2>&1 | tr '\r' '\n' | grep version | awk '{print $3}')"
@@ -101,7 +125,7 @@ jdk_version() {
         else
             result="$(echo "${version}" | awk -F '.' '{print $1}')"
         fi
-        echo "INFO: jdk_version ${result}" >>"${LOG_DIR}/be.out"
+        echo "INFO: jdk_version ${result}" >>"${STDOUT_LOGGER}"
     fi
     echo "${result}"
     return 0
@@ -218,7 +242,7 @@ export CLASSPATH="${DORIS_HOME}/conf/:${DORIS_CLASSPATH}:${CLASSPATH}"
 # DORIS_CLASSPATH is for self-managed jni
 export DORIS_CLASSPATH="-Djava.class.path=${DORIS_CLASSPATH}"
 
-#echo ${DORIS_CLASSPATH}
+# log ${DORIS_CLASSPATH}
 
 export LD_LIBRARY_PATH="${DORIS_HOME}/lib/hadoop_hdfs/native:${LD_LIBRARY_PATH}"
 
@@ -228,18 +252,6 @@ export ODBCSYSINI="${DORIS_HOME}/conf"
 # support utf8 for oracle database
 export NLS_LANG='AMERICAN_AMERICA.AL32UTF8'
 
-while read -r line; do
-    envline="$(echo "${line}" |
-        sed 's/[[:blank:]]*=[[:blank:]]*/=/g' |
-        sed 's/^[[:blank:]]*//g' |
-        grep -E "^[[:upper:]]([[:upper:]]|_|[[:digit:]])*=" ||
-        true)"
-    envline="$(eval "echo ${envline}")"
-    if [[ "${envline}" == *"="* ]]; then
-        eval 'export "${envline}"'
-    fi
-done <"${DORIS_HOME}/conf/be.conf"
-
 if [[ -e "${DORIS_HOME}/bin/palo_env.sh" ]]; then
     # shellcheck disable=1091
     source "${DORIS_HOME}/bin/palo_env.sh"
@@ -257,7 +269,7 @@ fi
 
 for var in http_proxy HTTP_PROXY https_proxy HTTPS_PROXY; do
     if [[ -n ${!var} ]]; then
-        echo "env '${var}' = '${!var}', need unset it using 'unset ${var}'"
+        log "env '${var}' = '${!var}', need unset it using 'unset ${var}'"
         exit 1
     fi
 done
@@ -278,7 +290,7 @@ if [[ -f "${pidfile}" ]]; then
 fi
 
 chmod 550 "${DORIS_HOME}/lib/doris_be"
-echo "Start time: $(date)" >>"${LOG_DIR}/be.out"
+log "Start time: $(date)"
 
 if [[ ! -f '/bin/limit3' ]]; then
     LIMIT=''
@@ -329,7 +341,7 @@ set_tcmalloc_heap_limit() {
     fi
 
     if [[ "${mem_limit_mb}" -gt "${total_mem_mb}" ]]; then
-        echo "mem_limit is larger than the total memory of the server. ${mem_limit_mb} > ${total_mem_mb}"
+        log "mem_limit is larger than the total memory of the server. ${mem_limit_mb} > ${total_mem_mb}"
         return 1
     fi
     export TCMALLOC_HEAP_LIMIT_MB=${mem_limit_mb}
@@ -377,9 +389,9 @@ fi
 # set LIBHDFS_OPTS for hadoop libhdfs
 export LIBHDFS_OPTS="${final_java_opt}"
 
-# echo "CLASSPATH: ${CLASSPATH}"
-# echo "LD_LIBRARY_PATH: ${LD_LIBRARY_PATH}"
-# echo "LIBHDFS_OPTS: ${LIBHDFS_OPTS}"
+# log "CLASSPATH: ${CLASSPATH}"
+# log "LD_LIBRARY_PATH: ${LD_LIBRARY_PATH}"
+# log "LIBHDFS_OPTS: ${LIBHDFS_OPTS}"
 
 if [[ -z ${JEMALLOC_CONF} ]]; then
     JEMALLOC_CONF="percpu_arena:percpu,background_thread:true,metadata_thp:auto,muzzy_decay_ms:15000,dirty_decay_ms:15000,oversize_threshold:0,prof:false,lg_prof_interval:32,lg_prof_sample:19,prof_gdump:false,prof_accum:false,prof_leak:false,prof_final:false"

diff --git a/regression-test/framework/pom.xml b/regression-test/framework/pom.xml
@@ -226,7 +226,7 @@ under the License.
         <dependency>
             <groupId>com.google.guava</groupId>
             <artifactId>guava</artifactId>
-            <version>31.0.1-jre</version>
+            <version>32.1.2-jre</version>
         </dependency>
         <dependency>
             <groupId>org.codehaus.janino</groupId>