optimize: optimize config and server module log (#2558)

config/seata-config-core/src/main/java/io/seata/config/ConfigurationFactory.java

@@ -68,7 +68,7 @@ public final class ConfigurationFactory {
         } catch (EnhancedServiceNotFoundException ignore) {
 
         } catch (Exception e) {
-            LOGGER.warn("failed to load extConfiguration:{}", e.getMessage(), e);
+            LOGGER.error("failed to load extConfiguration:{}", e.getMessage(), e);
         }
         CURRENT_FILE_INSTANCE = null == extConfiguration ? configuration : extConfiguration;
     }
@@ -120,7 +120,7 @@ private static Configuration buildConfiguration() {
             } catch (EnhancedServiceNotFoundException ignore) {
 
             } catch (Exception e) {
-                LOGGER.warn("failed to load extConfiguration:{}", e.getMessage(), e);
+                LOGGER.error("failed to load extConfiguration:{}", e.getMessage(), e);
             }
             return null == extConfiguration ? configuration : extConfiguration;
         } else {

config/seata-config-core/src/main/java/io/seata/config/FileConfiguration.java

@@ -269,8 +269,8 @@ public void run() {
                 } catch (Exception e) {
                     setFailResult(configFuture);
                     if (LOGGER.isDebugEnabled()) {
-                        LOGGER.debug("Could not found property {}, try to use default value instead.",
-                            configFuture.getDataId());
+                        LOGGER.debug("Could not found property {}, try to use default value instead. exception:{}",
+                            configFuture.getDataId(), e.getMessage());
                     }
                 }
             }

server/src/main/java/io/seata/server/coordinator/AbstractCore.java

@@ -83,17 +83,19 @@ public Long branchRegister(BranchType branchType, String resourceId, String clie
                         .format("Failed to store branch xid = %s branchId = %s", globalSession.getXid(),
                                 branchSession.getBranchId()), ex);
             }
-            LOGGER.info("Successfully register branch xid = {}, branchId = {}", globalSession.getXid(),
-                    branchSession.getBranchId());
+            if (LOGGER.isInfoEnabled()) {
+                LOGGER.info("Register branch successfully, xid = {}, branchId = {}, resourceId = {} ,lockKeys = {}",
+                    globalSession.getXid(), branchSession.getBranchId(), resourceId, lockKeys);
+            }
             return branchSession.getBranchId();
         });
     }
 
     protected void globalSessionStatusCheck(GlobalSession globalSession) throws GlobalTransactionException {
         if (!globalSession.isActive()) {
-            throw new GlobalTransactionException(GlobalTransactionNotActive, String
-                    .format("Could not register branch into global session xid = %s status = %s",
-                            globalSession.getXid(), globalSession.getStatus()));
+            throw new GlobalTransactionException(GlobalTransactionNotActive, String.format(
+                "Could not register branch into global session xid = %s status = %s, cause by globalSession not active",
+                globalSession.getXid(), globalSession.getStatus()));
         }
         if (globalSession.getStatus() != GlobalStatus.Begin) {
             throw new GlobalTransactionException(GlobalTransactionStatusInvalid, String
@@ -115,7 +117,7 @@ private GlobalSession assertGlobalSessionNotNull(String xid, boolean withBranchS
         GlobalSession globalSession = SessionHolder.findGlobalSession(xid, withBranchSessions);
         if (globalSession == null) {
             throw new GlobalTransactionException(TransactionExceptionCode.GlobalTransactionNotExist,
-                    String.format("Could not found global transaction xid = %s", xid));
+                    String.format("Could not found global transaction xid = %s, may be has finished.", xid));
         }
         return globalSession;
     }
@@ -132,8 +134,10 @@ public void branchReport(BranchType branchType, String xid, long branchId, Branc
         globalSession.addSessionLifecycleListener(SessionHolder.getRootSessionManager());
         globalSession.changeBranchStatus(branchSession, status);
 
-        LOGGER.info("Successfully branch report xid = {}, branchId = {}", globalSession.getXid(),
+        if (LOGGER.isInfoEnabled()) {
+            LOGGER.info("Report branch status successfully, xid = {}, branchId = {}", globalSession.getXid(),
                 branchSession.getBranchId());
+        }
     }
 
     @Override

server/src/main/java/io/seata/server/coordinator/DefaultCoordinator.java

@@ -156,9 +156,8 @@ protected void doGlobalBegin(GlobalBeginRequest request, GlobalBeginResponse res
         response.setXid(core.begin(rpcContext.getApplicationId(), rpcContext.getTransactionServiceGroup(),
             request.getTransactionName(), request.getTimeout()));
         if (LOGGER.isInfoEnabled()) {
-            LOGGER.info("begin new global transaction applicationId: {},transactionServiceGroup:{}, transactionName: "
-                    + "{},timeout:{},xid:{}", rpcContext.getApplicationId(), rpcContext.getTransactionServiceGroup(),
-                request.getTransactionName(), request.getTimeout(), response.getXid());
+            LOGGER.info("Begin new global transaction applicationId: {},transactionServiceGroup: {}, transactionName: {},timeout:{},xid:{}",
+                rpcContext.getApplicationId(), rpcContext.getTransactionServiceGroup(), request.getTransactionName(), request.getTimeout(), response.getXid());
         }
     }
 
@@ -219,7 +218,7 @@ protected void timeoutCheck() throws TransactionException {
             return;
         }
         if (allSessions.size() > 0 && LOGGER.isDebugEnabled()) {
-            LOGGER.debug("Transaction Timeout Check Begin: " + allSessions.size());
+            LOGGER.debug("Global transaction timeout check begin, size: {}", allSessions.size());
         }
         for (GlobalSession globalSession : allSessions) {
             if (LOGGER.isDebugEnabled()) {
@@ -246,14 +245,14 @@ protected void timeoutCheck() throws TransactionException {
             if (!shouldTimeout) {
                 continue;
             }
-            LOGGER.info("Global transaction[" + globalSession.getXid() + "] is timeout and will be rolled back.");
+            LOGGER.info("Global transaction[{}] is timeout and will be rollback.", globalSession.getXid());
 
             globalSession.addSessionLifecycleListener(SessionHolder.getRetryRollbackingSessionManager());
             SessionHolder.getRetryRollbackingSessionManager().addGlobalSession(globalSession);
 
         }
         if (allSessions.size() > 0 && LOGGER.isDebugEnabled()) {
-            LOGGER.debug("Transaction Timeout Check End. ");
+            LOGGER.debug("Global transaction timeout check end. ");
         }
 
     }
@@ -281,14 +280,13 @@ protected void handleRetryRollbacking() {
                      * Prevent thread safety issues
                      */
                     SessionHolder.getRetryRollbackingSessionManager().removeGlobalSession(rollbackingSession);
-                    LOGGER.error("GlobalSession rollback retry timeout and removed [{}]", rollbackingSession.getXid());
+                    LOGGER.info("Global transaction rollback retry timeout and has removed [{}]", rollbackingSession.getXid());
                     continue;
                 }
                 rollbackingSession.addSessionLifecycleListener(SessionHolder.getRootSessionManager());
                 core.doGlobalRollback(rollbackingSession, true);
             } catch (TransactionException ex) {
-                LOGGER.info("Failed to retry rollbacking [{}] {} {}", rollbackingSession.getXid(), ex.getCode(),
-                    ex.getMessage());
+                LOGGER.info("Failed to retry rollbacking [{}] {} {}", rollbackingSession.getXid(), ex.getCode(), ex.getMessage());
             }
         }
     }
@@ -309,26 +307,19 @@ protected void handleRetryCommitting() {
                      * Prevent thread safety issues
                      */
                     SessionHolder.getRetryCommittingSessionManager().removeGlobalSession(committingSession);
-                    LOGGER.error("GlobalSession commit retry timeout and removed [{}]", committingSession.getXid());
+                    LOGGER.error("Global transaction commit retry timeout and has removed [{}]", committingSession.getXid());
                     continue;
                 }
                 committingSession.addSessionLifecycleListener(SessionHolder.getRootSessionManager());
                 core.doGlobalCommit(committingSession, true);
             } catch (TransactionException ex) {
-                LOGGER.info("Failed to retry committing [{}] {} {}", committingSession.getXid(), ex.getCode(),
-                    ex.getMessage());
+                LOGGER.info("Failed to retry committing [{}] {} {}", committingSession.getXid(), ex.getCode(), ex.getMessage());
             }
         }
     }
 
     private boolean isRetryTimeout(long now, long timeout, long beginTime) {
-        /**
-         * Start timing when the session begin
-         */
-        if (timeout >= ALWAYS_RETRY_BOUNDARY && now - beginTime > timeout) {
-            return true;
-        }
-        return false;
+        return timeout >= ALWAYS_RETRY_BOUNDARY && now - beginTime > timeout;
     }
 
     /**
@@ -349,8 +340,7 @@ protected void handleAsyncCommitting() {
                 asyncCommittingSession.addSessionLifecycleListener(SessionHolder.getRootSessionManager());
                 core.doGlobalCommit(asyncCommittingSession, true);
             } catch (TransactionException ex) {
-                LOGGER.error("Failed to async committing [{}] {} {}", asyncCommittingSession.getXid(), ex.getCode(),
-                    ex.getMessage(), ex);
+                LOGGER.error("Failed to async committing [{}] {} {}", asyncCommittingSession.getXid(), ex.getCode(), ex.getMessage(), ex);
             }
         }
     }
@@ -376,7 +366,7 @@ protected void undoLogDelete() {
             try {
                 messageSender.sendASyncRequest(channelEntry.getValue(), deleteRequest);
             } catch (Exception e) {
-                LOGGER.error("Failed to async delete undo log resourceId = " + resourceId);
+                LOGGER.error("Failed to async delete undo log resourceId = {}, exception: {}", resourceId, e.getMessage());
             }
         }
     }

server/src/main/java/io/seata/server/coordinator/DefaultCore.java

@@ -192,12 +192,12 @@ public boolean doGlobalCommit(GlobalSession globalSession, boolean retrying) thr
                             continue;
                         case PhaseTwo_CommitFailed_Unretryable:
                             if (globalSession.canBeCommittedAsync()) {
-                                LOGGER.error("By [{}], failed to commit branch {}", branchStatus, branchSession);
+                                LOGGER.error(
+                                    "Committing branch transaction[{}], status: PhaseTwo_CommitFailed_Unretryable, please check the business log.", branchSession.getBranchId());
                                 continue;
                             } else {
                                 SessionHelper.endCommitFailed(globalSession);
-                                LOGGER.error("Finally, failed to commit global[{}] since branch[{}] commit failed",
-                                        globalSession.getXid(), branchSession.getBranchId());
+                                LOGGER.error("Committing global transaction[{}] finally failed, caused by branch transaction[{}] commit failed.", globalSession.getXid(), branchSession.getBranchId());
                                 return false;
                             }
                         default:
@@ -206,17 +206,17 @@ public boolean doGlobalCommit(GlobalSession globalSession, boolean retrying) thr
                                 return false;
                             }
                             if (globalSession.canBeCommittedAsync()) {
-                                LOGGER.error("By [{}], failed to commit branch {}", branchStatus, branchSession);
+                                LOGGER.error("Committing branch transaction[{}], status:{} and will retry later",
+                                    branchSession.getBranchId(), branchStatus);
                                 continue;
                             } else {
                                 LOGGER.error(
-                                        "Failed to commit global[{}] since branch[{}] commit failed, will retry later.",
-                                        globalSession.getXid(), branchSession.getBranchId());
+                                    "Committing global transaction[{}] failed, caused by branch transaction[{}] commit failed, will retry later.", globalSession.getXid(), branchSession.getBranchId());
                                 return false;
                             }
                     }
                 } catch (Exception ex) {
-                    StackTraceLogger.error(LOGGER, ex, "Exception committing branch {}",
+                    StackTraceLogger.error(LOGGER, ex, "Committing branch transaction exception: {}",
                         new String[] {branchSession.toString()});
                     if (!retrying) {
                         globalSession.queueToRetryCommit();
@@ -225,7 +225,7 @@ public boolean doGlobalCommit(GlobalSession globalSession, boolean retrying) thr
                 }
             }
             if (globalSession.hasBranch()) {
-                LOGGER.info("Global[{}] committing is NOT done.", globalSession.getXid());
+                LOGGER.info("Committing global transaction is NOT done, xid = {}.", globalSession.getXid());
                 return false;
             }
         }
@@ -237,7 +237,7 @@ public boolean doGlobalCommit(GlobalSession globalSession, boolean retrying) thr
                     globalSession.getTransactionName(), globalSession.getBeginTime(), System.currentTimeMillis(),
                     globalSession.getStatus()));
 
-            LOGGER.info("Global[{}] committing is successfully done.", globalSession.getXid());
+            LOGGER.info("Committing global transaction is successfully done, xid = {}.", globalSession.getXid());
         }
         return success;
     }
@@ -287,26 +287,23 @@ public boolean doGlobalRollback(GlobalSession globalSession, boolean retrying) t
                     switch (branchStatus) {
                         case PhaseTwo_Rollbacked:
                             globalSession.removeBranch(branchSession);
-                            LOGGER.info("Successfully rollback branch xid={} branchId={}", globalSession.getXid(),
-                                    branchSession.getBranchId());
+                            LOGGER.info("Rollback branch transaction  successfully, xid = {} branchId = {}", globalSession.getXid(), branchSession.getBranchId());
                             continue;
                         case PhaseTwo_RollbackFailed_Unretryable:
                             SessionHelper.endRollbackFailed(globalSession);
-                            LOGGER.info("Failed to rollback branch and stop retry xid={} branchId={}",
-                                    globalSession.getXid(), branchSession.getBranchId());
+                            LOGGER.info("Rollback branch transaction fail and stop retry, xid = {} branchId = {}", globalSession.getXid(), branchSession.getBranchId());
                             return false;
                         default:
-                            LOGGER.info("Failed to rollback branch xid={} branchId={}", globalSession.getXid(),
-                                    branchSession.getBranchId());
+                            LOGGER.info("Rollback branch transaction fail and will retry, xid = {} branchId = {}", globalSession.getXid(), branchSession.getBranchId());
                             if (!retrying) {
                                 globalSession.queueToRetryRollback();
                             }
                             return false;
                     }
                 } catch (Exception ex) {
-                    StackTraceLogger.error(LOGGER, ex, "Exception rollbacking branch xid={} branchId={} error msg={}",
-                        new String[] {globalSession.getXid(), String.valueOf(branchSession.getBranchId()),
-                            ex.getMessage()});
+                    StackTraceLogger.error(LOGGER, ex,
+                        "Rollback branch transaction exception, xid = {} branchId = {} exception = {}",
+                        new String[] {globalSession.getXid(), String.valueOf(branchSession.getBranchId()), ex.getMessage()});
                     if (!retrying) {
                         globalSession.queueToRetryRollback();
                     }
@@ -322,7 +319,7 @@ public boolean doGlobalRollback(GlobalSession globalSession, boolean retrying) t
             // failure due to data changes.
             GlobalSession globalSessionTwice = SessionHolder.findGlobalSession(globalSession.getXid());
             if (globalSessionTwice != null && globalSessionTwice.hasBranch()) {
-                LOGGER.info("Global[{}] rollbacking is NOT done.", globalSession.getXid());
+                LOGGER.info("Rollbacking global transaction is NOT done, xid = {}.", globalSession.getXid());
                 return false;
             }
         }
@@ -334,7 +331,7 @@ public boolean doGlobalRollback(GlobalSession globalSession, boolean retrying) t
                     globalSession.getTransactionName(), globalSession.getBeginTime(), System.currentTimeMillis(),
                     globalSession.getStatus()));
 
-            LOGGER.info("Successfully rollback global, xid = {}", globalSession.getXid());
+            LOGGER.info("Rollback global transaction successfully, xid = {}.", globalSession.getXid());
         }
         return success;
     }