[close #396] upgrade log4j and slf4j

pom.xml

@@ -63,8 +63,8 @@
         <project.reporting.outputEncoding>UTF-8</project.reporting.outputEncoding>
         <rocksdb.version>6.22.1.1</rocksdb.version>
         <protobuf.version>3.5.1</protobuf.version>
-        <log4j.version>1.2.17</log4j.version>
-        <slf4j.version>1.7.16</slf4j.version>
+        <log4j.version>2.15</log4j.version>
+        <slf4j.version>2.0.0-alpha5</slf4j.version>
         <grpc.version>1.38.0</grpc.version>
         <netty.tcnative.version>2.0.34.Final</netty.tcnative.version>
         <gson.version>2.8.5</gson.version>

src/main/java/org/tikv/cdc/RegionCDCClient.java

@@ -26,6 +26,7 @@
 import org.tikv.kvproto.Coprocessor.KeyRange;
 
 class RegionCDCClient implements AutoCloseable, StreamObserver<ChangeDataEvent> {
+
   private static final Logger LOGGER = LoggerFactory.getLogger(RegionCDCClient.class);
   private static final AtomicLong REQ_ID_COUNTER = new AtomicLong(0);
   private static final Set<LogType> ALLOWED_LOGTYPE =
@@ -127,7 +128,7 @@ public void close() throws Exception {
       channel.shutdown();
     }
     try {
-      LOGGER.debug("awaitTermination (region: {})", region.getId());
+      LOGGER.atDebug().log("awaitTermination (region: {})", region.getId());
       channel.awaitTermination(60, TimeUnit.SECONDS);
     } catch (final InterruptedException e) {
       LOGGER.error("Failed to shutdown channel(regionId: {})", region.getId());
@@ -178,7 +179,7 @@ public void onNext(final ChangeDataEvent event) {
   }
 
   private void submitEvent(final CDCEvent event) {
-    LOGGER.debug("submit event: {}", event);
+    LOGGER.atDebug().log("submit event: {}", event);
     eventConsumer.accept(event);
   }
 }

src/main/java/org/tikv/common/AbstractGRPCClient.java

@@ -42,6 +42,7 @@ public abstract class AbstractGRPCClient<
         BlockingStubT extends AbstractStub<BlockingStubT>,
         FutureStubT extends AbstractFutureStub<FutureStubT>>
     implements AutoCloseable {
+
   protected final Logger logger = LoggerFactory.getLogger(this.getClass());
   protected final ChannelFactory channelFactory;
   protected TiConfiguration conf;
@@ -105,7 +106,7 @@ protected <ReqT, RespT> void callAsyncWithRetry(
       Supplier<ReqT> requestFactory,
       StreamObserver<RespT> responseObserver,
       ErrorHandler<RespT> handler) {
-    logger.debug(String.format("Calling %s...", method.getFullMethodName()));
+    logger.atDebug().log("Calling {}...", method.getFullMethodName());
 
     RetryPolicy.Builder<RespT> builder = new Builder<>(backOffer);
     builder
@@ -121,15 +122,15 @@ protected <ReqT, RespT> void callAsyncWithRetry(
             },
             method.getFullMethodName(),
             backOffer);
-    logger.debug(String.format("leaving %s...", method.getFullMethodName()));
+    logger.atDebug().log("Leaving {}...", method.getFullMethodName());
   }
 
   <ReqT, RespT> StreamObserver<ReqT> callBidiStreamingWithRetry(
       BackOffer backOffer,
       MethodDescriptor<ReqT, RespT> method,
       StreamObserver<RespT> responseObserver,
       ErrorHandler<StreamObserver<ReqT>> handler) {
-    logger.debug(String.format("Calling %s...", method.getFullMethodName()));
+    logger.atDebug().log("Calling {}...", method.getFullMethodName());
 
     RetryPolicy.Builder<StreamObserver<ReqT>> builder = new Builder<>(backOffer);
     StreamObserver<ReqT> observer =
@@ -143,7 +144,7 @@ <ReqT, RespT> StreamObserver<ReqT> callBidiStreamingWithRetry(
                 },
                 method.getFullMethodName(),
                 backOffer);
-    logger.debug(String.format("leaving %s...", method.getFullMethodName()));
+    logger.atDebug().log("Leaving {}...", method.getFullMethodName());
     return observer;
   }
 
@@ -152,7 +153,7 @@ public <ReqT, RespT> StreamingResponse callServerStreamingWithRetry(
       MethodDescriptor<ReqT, RespT> method,
       Supplier<ReqT> requestFactory,
       ErrorHandler<StreamingResponse> handler) {
-    logger.debug(String.format("Calling %s...", method.getFullMethodName()));
+    logger.atDebug().log("Calling {}...", method.getFullMethodName());
 
     RetryPolicy.Builder<StreamingResponse> builder = new Builder<>(backOffer);
     StreamingResponse response =
@@ -167,7 +168,7 @@ public <ReqT, RespT> StreamingResponse callServerStreamingWithRetry(
                 },
                 method.getFullMethodName(),
                 backOffer);
-    logger.debug(String.format("leaving %s...", method.getFullMethodName()));
+    logger.atDebug().log("Leaving {}...", method.getFullMethodName());
     return response;
   }
 

src/main/java/org/tikv/common/catalog/CatalogTransaction.java

@@ -37,6 +37,7 @@
 import org.tikv.common.util.Pair;
 
 public class CatalogTransaction {
+
   protected static final Logger logger = LoggerFactory.getLogger(CatalogTransaction.class);
   private final Snapshot snapshot;
 
@@ -48,7 +49,11 @@ public static <T> T parseFromJson(ByteString json, Class<T> cls) {
     Objects.requireNonNull(json, "json is null");
     Objects.requireNonNull(cls, "cls is null");
 
-    logger.debug(String.format("Parse Json %s : %s", cls.getSimpleName(), json.toStringUtf8()));
+    logger
+        .atDebug()
+        .addArgument(cls::getSimpleName)
+        .addArgument(json::toStringUtf8)
+        .log("Parse Json {} : {}");
     ObjectMapper mapper = new ObjectMapper();
     try {
       return mapper.readValue(json.toStringUtf8(), cls);

src/main/java/org/tikv/common/importer/ImporterStoreClient.java

@@ -191,6 +191,7 @@ protected ImportSSTGrpc.ImportSSTStub getStub() {
   public void close() throws Exception {}
 
   public static class ImporterStoreClientBuilder<RequestClass, ResponseClass> {
+
     private final TiConfiguration conf;
     private final ChannelFactory channelFactory;
     private final RegionManager regionManager;
@@ -214,7 +215,7 @@ public synchronized ImporterStoreClient build(TiStore store) throws GrpcExceptio
       Objects.requireNonNull(store, "store is null");
 
       String addressStr = store.getStore().getAddress();
-      logger.debug(String.format("Create region store client on address %s", addressStr));
+      logger.atDebug().log("Create region store client on address {}", addressStr);
 
       ManagedChannel channel = channelFactory.getChannel(addressStr, pdClient.getHostMapping());
       ImportSSTGrpc.ImportSSTBlockingStub blockingStub = ImportSSTGrpc.newBlockingStub(channel);

src/main/java/org/tikv/common/log/SlowLogImpl.java

@@ -73,7 +73,7 @@ public void setError(Throwable err) {
   public void log() {
     long currentMS = System.currentTimeMillis();
     if (error != null || (slowThresholdMS >= 0 && currentMS - startMS > slowThresholdMS)) {
-      logger.warn("SlowLog:" + getSlowLogString(currentMS));
+      logger.atWarn().addArgument(() -> getSlowLogString(currentMS)).log("SlowLog:{}");
     }
   }
 

src/main/java/org/tikv/common/operation/PDErrorHandler.java

@@ -32,6 +32,7 @@
 import org.tikv.kvproto.Pdpb;
 
 public class PDErrorHandler<RespT> implements ErrorHandler<RespT> {
+
   public static final Function<Pdpb.GetRegionResponse, PDError> getRegionResponseErrorExtractor =
       r ->
           r.getHeader().hasError()
@@ -62,7 +63,7 @@ public boolean handleResponseError(BackOffer backOffer, RespT resp) {
           client.updateLeaderOrforwardFollower();
           return true;
         case REGION_PEER_NOT_ELECTED:
-          logger.debug(error.getMessage());
+          logger.atDebug().log(error.getMessage());
           backOffer.doBackOff(
               BackOffFunction.BackOffFuncType.BoPDRPC, new GrpcException(error.toString()));
           return true;

src/main/java/org/tikv/common/predicates/TiKVScanAnalyzer.java

@@ -57,6 +57,7 @@
 import org.tikv.kvproto.Coprocessor.KeyRange;
 
 public class TiKVScanAnalyzer {
+
   private static final double INDEX_SCAN_COST_FACTOR = 1.2;
   private static final double TABLE_SCAN_COST_FACTOR = 1.0;
   private static final double DOUBLE_READ_COST_FACTOR = TABLE_SCAN_COST_FACTOR * 3;
@@ -437,6 +438,7 @@ boolean isCoveringIndex(
   }
 
   public static class TiKVScanPlan {
+
     private final Map<Long, List<KeyRange>> keyRanges;
     private final Set<Expression> filters;
     private final double cost;
@@ -502,6 +504,7 @@ public TiStoreType getStoreType() {
     }
 
     public static class Builder {
+
       private final String tableName;
       private final Logger logger = LoggerFactory.getLogger(getClass().getName());
       private Map<Long, List<KeyRange>> keyRanges;
@@ -593,17 +596,15 @@ private void debug(IndexScanType scanType) {
             plan = "None";
             desc = "";
         }
-        logger.debug(
-            "[Table:"
-                + tableName
-                + "]["
-                + plan
-                + ":"
-                + desc
-                + "] cost="
-                + cost
-                + " estimated row count="
-                + estimatedRowCount);
+        logger
+            .atDebug()
+            .log(
+                "[Table:{}][{}:{}] cost={} estimated row count={}",
+                tableName,
+                plan,
+                desc,
+                cost,
+                estimatedRowCount);
       }
 
       // TODO: Fine-grained statistics usage

src/main/java/org/tikv/common/region/AbstractRegionStoreClient.java

@@ -45,6 +45,7 @@
 public abstract class AbstractRegionStoreClient
     extends AbstractGRPCClient<TikvGrpc.TikvBlockingStub, TikvGrpc.TikvFutureStub>
     implements RegionErrorReceiver {
+
   private static final Logger logger = LoggerFactory.getLogger(AbstractRegionStoreClient.class);
 
   public static final Histogram SEEK_LEADER_STORE_DURATION =
@@ -109,9 +110,7 @@ public void close() throws GrpcException {}
    */
   @Override
   public boolean onNotLeader(TiRegion newRegion) {
-    if (logger.isDebugEnabled()) {
-      logger.debug(region + ", new leader = " + newRegion.getLeader().getStoreId());
-    }
+    logger.atDebug().log("{}, new leader = {}", region, newRegion.getLeader().getStoreId());
     // When switch leader fails or the region changed its region epoch,
     // it would be necessary to re-split task's key range for new region.
     if (!region.getRegionEpoch().equals(newRegion.getRegionEpoch())) {
@@ -353,6 +352,7 @@ private TiStore switchProxyStore() {
   }
 
   private static class SwitchLeaderTask {
+
     private final ListenableFuture<Kvrpcpb.RawGetResponse> task;
     private final Metapb.Peer peer;
 
@@ -363,6 +363,7 @@ private SwitchLeaderTask(ListenableFuture<Kvrpcpb.RawGetResponse> task, Metapb.P
   }
 
   private static class ForwardCheckTask {
+
     private final ListenableFuture<Kvrpcpb.RawGetResponse> task;
     private final Metapb.Store store;
 

src/main/java/org/tikv/common/region/RegionCache.java

@@ -16,6 +16,7 @@
 import org.tikv.common.util.BackOffer;
 
 public class RegionCache {
+
   private static final Logger logger = LoggerFactory.getLogger(RegionCache.class);
 
   private final Map<Long, TiRegion> regionCache;
@@ -43,26 +44,23 @@ public synchronized TiRegion getRegionByKey(ByteString key, BackOffer backOffer)
     } else {
       regionId = keyToRegionIdCache.get(Key.toRawKey(key));
     }
-    if (logger.isDebugEnabled()) {
-      logger.debug(
-          String.format("getRegionByKey key[%s] -> ID[%s]", formatBytesUTF8(key), regionId));
-    }
+    logger
+        .atDebug()
+        .addArgument(() -> formatBytesUTF8(key))
+        .addArgument(() -> regionId)
+        .log("getRegionByKey key[{}] -> ID[{}]");
 
     if (regionId == null) {
       return null;
     }
     TiRegion region;
     region = regionCache.get(regionId);
-    if (logger.isDebugEnabled()) {
-      logger.debug(String.format("getRegionByKey ID[%s] -> Region[%s]", regionId, region));
-    }
+    logger.atDebug().log("getRegionByKey ID[{}] -> Region[{}]", regionId, region);
     return region;
   }
 
   public synchronized TiRegion putRegion(TiRegion region) {
-    if (logger.isDebugEnabled()) {
-      logger.debug("putRegion: " + region);
-    }
+    logger.atDebug().log("putRegion: {}", region);
     TiRegion oldRegion = regionCache.get(region.getId());
     if (oldRegion != null) {
       if (oldRegion.getMeta().equals(region.getMeta())) {
@@ -79,9 +77,7 @@ public synchronized TiRegion putRegion(TiRegion region) {
   @Deprecated
   public synchronized TiRegion getRegionById(long regionId) {
     TiRegion region = regionCache.get(regionId);
-    if (logger.isDebugEnabled()) {
-      logger.debug(String.format("getRegionByKey ID[%s] -> Region[%s]", regionId, region));
-    }
+    logger.atDebug().log("getRegionByKey ID[{}] -> Region[{}]", regionId, region);
     return region;
   }
 
@@ -92,9 +88,7 @@ private synchronized TiRegion getRegionFromCache(long regionId) {
   /** Removes region associated with regionId from regionCache. */
   public synchronized void invalidateRegion(TiRegion region) {
     try {
-      if (logger.isDebugEnabled()) {
-        logger.debug(String.format("invalidateRegion ID[%s]", region.getId()));
-      }
+      logger.atDebug().log("invalidateRegion ID[{}]", region.getId());
       TiRegion oldRegion = regionCache.get(region.getId());
       if (oldRegion != null && oldRegion == region) {
         keyToRegionIdCache.remove(makeRange(region.getStartKey(), region.getEndKey()));
@@ -118,9 +112,7 @@ public synchronized void insertRegionToCache(TiRegion region) {
 
   public synchronized boolean updateRegion(TiRegion expected, TiRegion region) {
     try {
-      if (logger.isDebugEnabled()) {
-        logger.debug(String.format("invalidateRegion ID[%s]", region.getId()));
-      }
+      logger.atDebug().log("invalidateRegion ID[{}]", region.getId());
       TiRegion oldRegion = regionCache.get(region.getId());
       if (!expected.getMeta().equals(oldRegion.getMeta())) {
         return false;
@@ -162,9 +154,7 @@ public synchronized void invalidateAllRegionForStore(TiStore store) {
     List<TiRegion> regionToRemove = new ArrayList<>();
     for (TiRegion r : regionCache.values()) {
       if (r.getLeader().getStoreId() == store.getId()) {
-        if (logger.isDebugEnabled()) {
-          logger.debug(String.format("invalidateAllRegionForStore Region[%s]", r));
-        }
+        logger.atDebug().log("invalidateAllRegionForStore Region[{}]", r);
         regionToRemove.add(r);
       }
     }

src/main/java/org/tikv/common/region/RegionManager.java

@@ -44,6 +44,7 @@
 
 @SuppressWarnings("UnstableApiUsage")
 public class RegionManager {
+
   private static final Logger logger = LoggerFactory.getLogger(RegionManager.class);
   public static final Histogram GET_REGION_BY_KEY_REQUEST_LATENCY =
       Histogram.build()
@@ -105,7 +106,10 @@ public TiRegion getRegionByKey(ByteString key, BackOffer backOffer) {
     TiRegion region = cache.getRegionByKey(key, backOffer);
     try {
       if (region == null) {
-        logger.debug("Key not found in keyToRegionIdCache:" + formatBytesUTF8(key));
+        logger
+            .atDebug()
+            .addArgument(() -> formatBytesUTF8(key))
+            .log("Key not found in keyToRegionIdCache:{}");
         Pair<Metapb.Region, Metapb.Peer> regionAndLeader = pdClient.getRegionByKey(backOffer, key);
         region =
             cache.putRegion(createRegion(regionAndLeader.first, regionAndLeader.second, backOffer));