Ci/grpc hang watch grpc log

build.gradle

@@ -75,8 +75,9 @@ subprojects {
     }
 
     dependencies {
-        implementation group: 'org.slf4j', name: 'slf4j-api', version: '1.7.25'
-        implementation group: 'org.slf4j', name: 'jcl-over-slf4j', version: '1.7.25'
+        implementation group: 'org.slf4j', name: 'slf4j-api', version: '1.7.36'
+        implementation group: 'org.slf4j', name: 'jcl-over-slf4j', version: '1.7.36'
+        implementation group: 'org.slf4j', name: 'jul-to-slf4j', version: '1.7.36'
         implementation group: 'ch.qos.logback', name: 'logback-classic', version: '1.2.13'
         implementation "com.google.code.findbugs:jsr305:3.0.0"
         implementation group: 'org.springframework', name: 'spring-context', version: "${springVersion}"

common/src/main/java/org/tron/common/log/LogService.java

@@ -2,24 +2,26 @@
 
 import ch.qos.logback.classic.LoggerContext;
 import ch.qos.logback.classic.joran.JoranConfigurator;
+import ch.qos.logback.core.util.StatusPrinter;
 import java.io.File;
 import org.slf4j.LoggerFactory;
 import org.tron.core.exception.TronError;
 
 public class LogService {
 
   public static void load(String path) {
+    LoggerContext lc = (LoggerContext) LoggerFactory.getILoggerFactory();
     try {
       File file = new File(path);
       if (!file.exists() || !file.isFile() || !file.canRead()) {
         return;
       }
-      LoggerContext lc = (LoggerContext) LoggerFactory.getILoggerFactory();
       JoranConfigurator configurator = new JoranConfigurator();
       configurator.setContext(lc);
       lc.reset();
       configurator.doConfigure(file);
     } catch (Exception e) {
+      StatusPrinter.printInCaseOfErrorsOrWarnings(lc);
       throw new TronError(e, TronError.ErrCode.LOG_LOAD);
     }
   }

common/src/main/java/org/tron/common/parameter/CommonParameter.java

@@ -4,10 +4,15 @@
 import java.net.InetAddress;
 import java.net.InetSocketAddress;
 import java.util.ArrayList;
+import java.util.Enumeration;
 import java.util.List;
 import java.util.Set;
+import java.util.logging.Level;
+import java.util.logging.LogManager;
+import java.util.logging.Logger;
 import lombok.Getter;
 import lombok.Setter;
+import org.slf4j.bridge.SLF4JBridgeHandler;
 import org.tron.common.args.GenesisBlock;
 import org.tron.common.config.DbBackupConfig;
 import org.tron.common.cron.CronExpression;
@@ -750,6 +755,31 @@ public class CommonParameter {
   @Setter
   public long allowTvmBlob;
 
+  static {
+    LogManager.getLogManager().reset();
+    SLF4JBridgeHandler.removeHandlersForRootLogger();
+    SLF4JBridgeHandler.install();
+    Logger.getLogger("").setLevel(Level.ALL); // Root logger.
+    LogManager logManager = LogManager.getLogManager();
+
+    setLoggerLevel("io.grpc");
+    setLoggerLevel("io.netty");
+
+    Enumeration<String> names = logManager.getLoggerNames();
+    while (names.hasMoreElements()) {
+      String name = names.nextElement();
+      if (name.startsWith("io.grpc") || name.startsWith("io.netty")) {
+        setLoggerLevel(name);
+      }
+    }
+  }
+
+  private static void setLoggerLevel(String name) {
+    Logger logger = Logger.getLogger(name);
+    logger.setLevel(Level.FINEST);
+    logger.setUseParentHandlers(true);
+  }
+
   private static double calcMaxTimeRatio() {
     //return max(2.0, min(5.0, 5 * 4.0 / max(Runtime.getRuntime().availableProcessors(), 1)));
     return 5.0;

common/src/main/java/org/tron/common/setting/RocksDbSettings.java

@@ -8,9 +8,7 @@
 import org.rocksdb.BlockBasedTableConfig;
 import org.rocksdb.BloomFilter;
 import org.rocksdb.ComparatorOptions;
-import org.rocksdb.InfoLogLevel;
 import org.rocksdb.LRUCache;
-import org.rocksdb.Logger;
 import org.rocksdb.Options;
 import org.rocksdb.RocksDB;
 import org.rocksdb.Statistics;
@@ -182,13 +180,6 @@ public static Options getOptionsByDbName(String dbName) {
     RocksDbSettings settings = getSettings();
 
     Options options = new Options();
-
-    options.setLogger(new Logger(options) {
-      @Override
-      protected void log(InfoLogLevel infoLogLevel, String logMsg) {
-        rocksDbLogger.info("{} {}", dbName, logMsg);
-      }
-    });
     // most of these options are suggested by https://github.com/facebook/rocksdb/wiki/Set-Up-Options
 
     // general options

common/src/main/java/org/tron/common/utils/DebugInterceptor.java

@@ -0,0 +1,95 @@
+package org.tron.common.utils;
+
+import io.grpc.CallOptions;
+import io.grpc.Channel;
+import io.grpc.ClientCall;
+import io.grpc.ClientInterceptor;
+import io.grpc.ForwardingClientCall;
+import io.grpc.ForwardingClientCallListener;
+import io.grpc.Metadata;
+import io.grpc.MethodDescriptor;
+import io.grpc.Status;
+import java.util.concurrent.atomic.AtomicLong;
+import lombok.extern.slf4j.Slf4j;
+
+@Slf4j(topic = "grpcClient")
+/**
+ * A gRPC ClientInterceptor that provides deep, event-level logging to debug complex
+ * concurrency and hanging issues. It meticulously logs the sequence of events across
+ * the application thread and gRPC's internal I/O threads.
+ */
+public class DebugInterceptor implements ClientInterceptor {
+
+  private final AtomicLong callIdCounter = new AtomicLong(0);
+
+  @Override
+  public <ReqT, RespT> ClientCall<ReqT, RespT> interceptCall(
+      MethodDescriptor<ReqT, RespT> method, CallOptions callOptions, Channel next) {
+    logger.debug("callId={}, event=interceptCall, method={}, callOptions={}",
+        callIdCounter.incrementAndGet(), method.getFullMethodName(), callOptions);
+    ClientCall<ReqT, RespT> call = next.newCall(method, callOptions);
+    return new ForwardingClientCall.SimpleForwardingClientCall<ReqT, RespT>(call) {
+
+      @Override
+      public void start(Listener<RespT> responseListener, Metadata headers) {
+        logger.debug("callId={}, event=start, headers={}", callIdCounter.get(), headers);
+        super.start(new ForwardingClientCallListener.SimpleForwardingClientCallListener<RespT>(
+            responseListener) {
+          @Override
+          public void onHeaders(Metadata headers) {
+            logger.debug("callId={}, event=onHeaders, headers={}", callIdCounter.get(), headers);
+            try {
+              super.onHeaders(headers);
+              logger.debug("callId={}, event=onHeaders completed", callIdCounter.get());
+            } catch (Exception e) {
+              logger.error("callId={}, event=onHeaders, exception={}", callIdCounter.get(),
+                  e.getMessage(), e);
+              throw e;
+            }
+          }
+
+          @Override
+          public void onClose(Status status, Metadata trailers) {
+            logger.debug("callId={}, event=onClose, status={}, trailers={}",
+                callIdCounter.get(), status, trailers);
+            try {
+              super.onClose(status, trailers);
+              logger.debug("callId={}, event=onClose completed", callIdCounter.get());
+            } catch (Exception e) {
+              logger.error("callId={}, event=onClose, exception={}", callIdCounter.get(),
+                  e.getMessage(), e);
+              throw e;
+            }
+          }
+
+          @Override
+          public void onMessage(RespT message) {
+            logger.debug("callId={}, event=onMessage, message={}", callIdCounter.get(), message);
+            try {
+              super.onMessage(message);
+              logger.debug("callId={}, event=onMessage completed", callIdCounter.get());
+            } catch (Exception e) {
+              logger.error("callId={}, event=onMessage, exception={}", callIdCounter.get(),
+                  e.getMessage(), e);
+              throw e;
+            }
+          }
+
+          public void onReady() {
+            logger.debug("callId={}, event=onReady", callIdCounter.get());
+            try {
+              super.onReady();
+              logger.debug("callId={}, event=onReady completed", callIdCounter.get());
+            } catch (Exception e) {
+              logger.error("callId={}, event=onReady, exception={}", callIdCounter.get(),
+                  e.getMessage(), e);
+              throw e;
+            }
+          }
+
+        }, headers);
+        logger.debug("callId={}, event=start completed", callIdCounter.get());
+      }
+    };
+  }
+}

common/src/main/java/org/tron/common/utils/TimeoutInterceptor.java

@@ -6,8 +6,10 @@
 import io.grpc.ClientInterceptor;
 import io.grpc.MethodDescriptor;
 import java.util.concurrent.TimeUnit;
+import lombok.extern.slf4j.Slf4j;
 
 
+@Slf4j(topic = "grpcClient")
 public class TimeoutInterceptor implements ClientInterceptor {
 
   private final long timeout;
@@ -24,7 +26,8 @@ public <ReqT, RespT> ClientCall<ReqT, RespT> interceptCall(
       MethodDescriptor<ReqT, RespT> method,
       CallOptions callOptions,
       Channel next) {
-    return next.newCall(method,
-        callOptions.withDeadlineAfter(timeout, TimeUnit.MILLISECONDS));
+    CallOptions options = callOptions.withDeadlineAfter(timeout, TimeUnit.MILLISECONDS);
+    logger.debug("Set options {} for method {}", options, method.getFullMethodName());
+    return next.newCall(method, options);
   }
 }