[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));