Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

optimize: optimize config and server module log #2558

Merged
merged 5 commits into from
Apr 15, 2020
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
Expand Down Expand Up @@ -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 {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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());
}
}
}
Expand Down
18 changes: 11 additions & 7 deletions server/src/main/java/io/seata/server/coordinator/AbstractCore.java
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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;
}
Expand All @@ -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
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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());
}
}

Expand Down Expand Up @@ -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()) {
Expand All @@ -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. ");
}

}
Expand Down Expand Up @@ -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());
}
}
}
Expand All @@ -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;
}

/**
Expand All @@ -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);
}
}
}
Expand All @@ -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());
}
}
}
Expand Down
37 changes: 17 additions & 20 deletions server/src/main/java/io/seata/server/coordinator/DefaultCore.java
Original file line number Diff line number Diff line change
Expand Up @@ -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:
Expand All @@ -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();
Expand All @@ -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;
}
}
Expand All @@ -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;
}
Expand Down Expand Up @@ -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();
}
Expand All @@ -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;
}
}
Expand All @@ -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;
}
Expand Down