背景
最近公司對原有單體應用進行業(yè)務拆分舌镶，將每個有自己特定功能的模塊作為一個微服務柱彻，每個微服務單獨部署，開發(fā)過程中遇到了一些問題餐胀，一是調(diào)用接口報錯哟楷，雖有打印日志，但不知道是哪個服務出了問題否灾，是前端傳參有問題吓蘑，還是系統(tǒng)A或者系統(tǒng)B提供的接口導致；二是接口出現(xiàn)性能問題時只能通過打印日志定位坟冲，三是log日志打印太隨意，應該打error級別日志溃蔫，使用info健提、warn級別等問題，總之伟叛，問題排查非常麻煩私痹。下面我們來導論一下這個問題。
解決思路
定義日志打印規(guī)范统刮，給每個請求生成一個唯一traceId紊遵，當請求調(diào)用其他服務時，我們傳遞這個traceId侥蒙。在輸出日志時暗膜，將這個traceId打印到日志文件中，這樣從日志文件中鞭衩，根據(jù)traceId就可以分析一個請求完整的調(diào)用鏈路学搜。
一、日志打印優(yōu)化實踐
1.1 日志打印規(guī)范
針對項目中日志級別亂打论衍，大量地輸出無效日志帶來的問題瑞佩，我們在項目中定義了如下規(guī)范：
1.【必須】排查問題用的數(shù)據(jù)量較大詳細日志打debug，關鍵業(yè)務流程節(jié)點坯台、第三方接口日志打info炬丸，不需要監(jiān)控的錯誤（如后臺表單參數(shù)校驗失敗等）打warn，需要監(jiān)控并處理的錯誤（系統(tǒng)不應該出現(xiàn)的錯誤）打error蜒蕾。
**2. **【必須】第三方接口根據(jù)情況盡可能打印完整入?yún)⒊鰠⒊砭妫绻麛?shù)據(jù)量較大的接口，至少用info打印關鍵字段咪啡，debug打印完整信息酸纲。
**3. **【必須】所有fallback打印error日志，包括調(diào)用參數(shù)瑟匆，觸發(fā)fallback的原因闽坡。
**4. **【建議】后臺管理的增刪改操作盡可能多記錄日志栽惶，以便快速定位問題。
全局異常捕獲類日志打印規(guī)范代碼實現(xiàn)：
@RestControllerAdvice
public class BaseGlobalExceptionHandler {
private static final Logger log = LoggerFactory.getLogger(BaseGlobalExceptionHandler.class);
@ExceptionHandler({BaseBizException.class})
@ResponseStatus(HttpStatus.BAD_REQUEST)
public BaseResult<?> baseBusinessExceptionHandler(BaseBizException exception) {
if (log.isWarnEnabled()) {
log.warn("[BizException]業(yè)務異常信息 ex={}", exception.getMessage(), exception);
}
return BaseResult.error(exception.getCode(), exception.getMessage());
}
@ExceptionHandler(MethodArgumentNotValidException.class)
@ResponseStatus(HttpStatus.BAD_REQUEST)
public BaseResult methodArgumentNotValidException(MethodArgumentNotValidException exception) {
return bindingResultHandler(exception.getBindingResult());
}
@ExceptionHandler(BindException.class)
@ResponseStatus(HttpStatus.BAD_REQUEST)
public BaseResult bindException(BindException exception) {
return bindingResultHandler(exception.getBindingResult());
}
public BaseResult bindingResultHandler(BindingResult bindingResult){
Map<String,String> errorMap = new HashMap<>(bindingResult.getFieldErrorCount());
if (bindingResult.hasErrors()) {
for (FieldError fieldError : bindingResult.getFieldErrors()) {
errorMap.put(fieldError.getField(), fieldError.getDefaultMessage());
}
}
if (log.isWarnEnabled()) {
log.warn("[bindingResult]參數(shù)校驗異常 ex={}", bindingResult);
}
return BaseResult.error(ErrorEnum.PARAM_ERROR.getCode(), ErrorEnum.PARAM_ERROR.getMessage(), errorMap);
}
@ExceptionHandler({Exception.class})
@ResponseStatus(HttpStatus.INTERNAL_SERVER_ERROR)
public BaseResult<?> exceptionHandler(Exception e) {
if (log.isErrorEnabled()) {
log.error("[InternalException]內(nèi)部異常信息 ex={}", e.getMessage(), e);
}
return BaseResult.error(BaseErrorEnum.UNKNOW_SYSTEM_ERROR);
}
}
業(yè)務代碼非error級別異常處理疾嗅，此處的異常因為是記錄日志導致的外厂，所以異常的時候，一是不影響主業(yè)務邏輯代承，二是不進行異常告警汁蝶。
@Transactional(rollbackFor = Exception.class)
public void updateWorkOrderStatus(WorkOrderStatusDto workOrderStatus) {
//......工單業(yè)務處理邏輯代碼省略
try {
// 記錄日志
List<WorkOrderFile> workOrderFiles = workOrderFileService.selectList(new QueryWrapper<WorkOrderFile>()
.lambda().eq(WorkOrderFile::getWorkOrderId, workOrderStatus.getWorkOrderId()));
List<Integer> fileIds = workOrderFiles.stream().map(WorkOrderFile::getFileId).collect(Collectors.toList());
saveWorkerOrderLog(workOrderStatus.getWorkOrderId(), workOrder.getDescription(), fileIds);
} catch (Exception e) {
// 工單狀態(tài)變更通知或記錄日志異常不影響業(yè)務正常執(zhí)行
log.warn("工單狀態(tài)變更通知或記錄日志異常", e);
}
}
業(yè)務代碼處理error級別異常。此處庫存異動處理失敗论悴，需要及時通知相關人員進行處理掖棉。
@Override
public void dealChangeFromBoh(InventoryChangeFromBohDto dto, String batchNo) {
//......業(yè)務處理代碼省略
// 庫存異動
try {
handleChangeFromBoh(dto);
} catch (Exception e) {
log.error("庫存異動，處理失敗,bohNo:{}", batchNo, e);
}
}
1.2 日志加入traceId
業(yè)務篩分后膀估，一個接口請求可能會涉及到多個服務幔亥，比如獲取門店商品接口，需要調(diào)用會員察纯、訂單帕棉、商品等服務完成數(shù)據(jù)構建，當獲取門店商品接口異常時饼记，很難找出哪個服務異常導致香伴。因此在不大改代碼的前提下使用一個traceId實現(xiàn)分布式鏈路追蹤。
APM組件目前比較流行的有Zipkin具则、Pinpoint即纲、SkyWalking、CAT博肋，大家可以根據(jù)實際的業(yè)務需求和場景進行選型崇裁，項目中我們使用Zipkin，主要是結(jié)合我們項目中使用的技術和業(yè)務需求束昵。
需在要生成traceId的所有工程中拔稳，pom.xml引入以下依賴
<dependency>
<groupId>org.springframework.cloud</groupId>
<artifactId>spring-cloud-starter-zipkin</artifactId>
</dependency>
由于需要給前端返回traceId，網(wǎng)關請求返回值需要加上如下代碼:
private void addTraceIdToHeader(ServerHttpResponse response) {
String traceId = Optional.ofNullable(tracer.currentSpan())
.map(Span::context)
.map(TraceContext::traceIdString)
.orElse(null);
if (StringUtils.isEmpty(traceId)) {
if (log.isInfoEnabled()) {
log.info("trace id empty");
}
return;
}
String header = HEADER_NAME_TRACE_ID;
if (log.isDebugEnabled()) {
log.debug("add trace id [{}] to header [{}]", traceId, header);
}
response.getHeaders().add(header, traceId);
}
加入traceId后服務端日志打印如下：
{"@timestamp":"2020-01-04T18:15:31.275+08:00","hostname":"service-order","severity":"INFO","service":"service-sale","trace":"6c9a14a717a52819","span":"6fef879e39f264f5","parent":"6c9a14a717a52819","exportable":"false","pid":"1","thread":"http-nio-30130-exec-3","class":"c.h.s.s.c.shop.FeeController","message":"獲取門店包裝費狀態(tài)"}
{"@timestamp":"2020-01-04T18:15:31.607+08:00","hostname":"service-sale","severity":"INFO","service":"service-sale","trace":"473d9eeea42d75fe","span":"310ae5240722958c","parent":"473d9eeea42d75fe","exportable":"false","pid":"1","thread":"http-nio-30130-exec-4","class":"c.h.s.s.s.u.s.i.UserSubscribeServiceImpl","message":"訂閱提醒 "}
前端請求返回結(jié)果新增X-trace-id參數(shù)：
Response Headers
Connection:keep-alive
Content-Type:application/json;charset=UTF-8
Date:Sat, 04 Jan 2020 08:48:34 GMT
Transfer-Encoding:chunked
X-trace-id:2a5a9283dfe955d0
1.3 traceId線程穿透及解決項目中遇到的問題
1.3.1 雖然使用Spring Cloud Sleuth為我們生成traceId锹雏，極大的減少了開發(fā)工作量巴比，但是在調(diào)用鏈路中如果使用了Thread或ThreadPoolExecutor，就會導致traceId無法穿透礁遵，如果不解決線程穿透問題轻绞，此類接口打印traceId有點雞肋。
1.3.2 通過網(wǎng)關發(fā)起的請求佣耐，接口如果超過10秒沒有執(zhí)行完連接就會斷開并返回接口請求超時提示信息政勃，舉個例子，當運營操作菜單批量綁定商品功能時(此功能有使用多線程)兼砖，只要執(zhí)行此功能奸远，前端基本上會報接口請求超時既棺，實際菜單批量綁定商品接口最后執(zhí)成功或失敗都有可能，但發(fā)起請求一端拿不到執(zhí)行結(jié)果信息懒叛，執(zhí)行進度和結(jié)果完全靠猜或長期積累的經(jīng)驗進行判斷丸冕，這類功能用戶使用體驗極差，問題也不好定位薛窥。
為解決以上問題胖烛，我們封裝了一個工具類：
/**
* 線程池需要使用的時候該service時，需要線程池使用sleuth的線程池定義诅迷，否則線程池無法向下傳遞
*
* @author zhangbowen@heytea.com
* @since 2019-12-27 09:31
*/
public interface LogManager {
/**
* 操作記錄begin 操作記錄開始,當有userId的時候則為人工操作佩番；沒有userId則為定時任務
*
* @param type
* 業(yè)務類型 批量發(fā)布、批量上架等
*/
void begin(Integer type);
/**
* 操作記錄end 操作執(zhí)行完成后罢杉，更新操作記錄的狀態(tài)
*
*/
void end();
/**
* 操作日志log 記錄操作日志,正常和錯誤日志都可以記錄
*
* @param type
* 1:正常 0：錯誤
* @param description
* 操作描述
*/
void log(Integer type, String description);
/**
* 操作日志success 記錄正常的操作日志
*
* @param description
* 操作描述
*/
void success(String description);
/**
* 操作日志error 記錄錯誤的操作日志
*
* @param description
* 操作描述
*/
void error(String description);
/**
* 批量新增操作日志
*
* @param executionLogDtoList
* 批量的操作日志
*/
void batchLog(List<ExecutionLogDto> executionLogDtoList);
/**
* 查詢操作日志
*
* @param traceId
* 鏈路id
* @return
*/
OperateLogDto findOperateLog(String traceId);
/**
* 生成新的traceId
*
* @return
*/
String newTraceId();
}
/**
* 線程池需要使用的時候該service時趟畏，需要線程池使用sleuth的線程池定義，否則traceId無法從線程池向下傳遞
*
* @author zhangbowen@heytea.com
* @since 2019-12-27 09:32
*/
@Component
@Slf4j
public class LogManagerImpl implements LogManager {
@Autowired
private MongoTemplate mongoTemplate;
@Autowired
private Tracing tracing;
@Autowired
private LogManager logManager;
/**
* 操作記錄begin 操作記錄開始,當有userId的時候則為人工操作屑那；沒有userId則為定時任務
*
* @param type
* 業(yè)務類型 批量發(fā)布、批量上架等
*/
@Override
public void begin(Integer type) {
try {
TraceContext traceContext = tracing.currentTraceContext().get();
String traceId = traceContext != null ? traceContext.traceIdString() : logManager.newTraceId();
//@formatter:off
OperateRecord operateRecord = new OperateRecord().setCreateTime(LocalDateTime.now())
.setStatus(OperateStatusEnum.BEGIN.getCode())
.setType(type).setTraceId(traceId);
//@formatter:on
BaseUser baseUser = RequestContextUtil.getBaseUser();
if (baseUser.getUserId() == null) {
// 定時任務
Integer userId = CommonConstant.DEFAULT_USER_ID;
log.info("【操作記錄begin】定時任務調(diào)用traceId:{},用戶id:{}", traceId, userId);
//@formatter:off
operateRecord.setOperateType(OperateTypeEnum.JOB.getCode())
.setUserId(userId);
//@formatter:on
} else {
// 人工調(diào)用
log.info("【操作記錄begin】人工調(diào)用調(diào)用traceId:{},用戶id:{}", traceId, baseUser.getUserId());
//@formatter:off
operateRecord.setOperateType(OperateTypeEnum.ARTIFICIAL.getCode())
.setUserId(baseUser.getUserId().intValue());
//@formatter:on
}
log.info("【操作記錄begin】插入操作記錄:{}", JSON.toJSONString(operateRecord));
mongoTemplate.insert(operateRecord);
} catch (Exception e) {
log.error("【操作記錄begin】操作失敗", e);
}
}
/**
* 操作記錄end 操作執(zhí)行完成后艘款，更新操作記錄的狀態(tài)
*
*/
@Override
public void end() {
try {
TraceContext traceContext = tracing.currentTraceContext().get();
if (traceContext == null) {
log.error("【操作記錄end】沒有traceId");
return;
}
String traceId = traceContext.traceIdString();
log.info("【操作記錄end】更新操作記錄 traceId:{}", JSON.toJSONString(traceId));
mongoTemplate.updateFirst(BasicQuery.query(Criteria.where(OperateRecordConstant.TRACE_ID).is(traceId)),
BasicUpdate.update(OperateRecordConstant.STATUS, OperateStatusEnum.END.getCode()), OperateRecord.class);
} catch (Exception e) {
log.error("【操作記錄end】操作失敗", e);
}
}
/**
* 操作日志log 記錄操作日志,正常和錯誤日志都可以記錄
*
* @param type
* 1:正常 0：錯誤
* @param description
* 操作描述
*/
@Override
public void log(Integer type, String description) {
try {
TraceContext traceContext = tracing.currentTraceContext().get();
if (traceContext == null) {
log.error("【操作日志log】沒有traceId");
return;
}
//@formatter:off
ExecutionLog executionLog = new ExecutionLog()
.setTraceId(traceContext.traceIdString())
.setDescription(description)
.setType(type)
.setCreateTime(LocalDateTime.now());
//@formatter:on
log.info("【操作日志log】插入執(zhí)行日志:{}", JSON.toJSONString(executionLog));
mongoTemplate.insert(executionLog);
} catch (Exception e) {
log.error("【操作日志log】操作失敗", e);
}
}
/**
* 操作日志success 記錄正常的操作日志
*
* @param description
* 操作描述
*/
@Override
public void success(String description) {
try {
TraceContext traceContext = tracing.currentTraceContext().get();
if (traceContext == null) {
log.error("【操作日志success】沒有traceId");
return;
}
//@formatter:off
ExecutionLog executionLog = new ExecutionLog()
.setTraceId(traceContext.traceIdString())
.setDescription(description)
.setType(ResultTypeEnum.SUCCESS.getCode())
.setCreateTime(LocalDateTime.now());
//@formatter:on
log.info("【操作日志success】插入執(zhí)行日志:{}", JSON.toJSONString(executionLog));
mongoTemplate.insert(executionLog);
} catch (Exception e) {
log.error("【操作日志success】操作失敗", e);
}
}
/**
* 操作日志error 記錄錯誤的操作日志
*
* @param description
* 操作描述
*/
@Override
public void error(String description) {
try {
TraceContext traceContext = tracing.currentTraceContext().get();
if (traceContext == null) {
log.error("【操作日志error】沒有traceId");
return;
}
//@formatter:off
ExecutionLog executionLog = new ExecutionLog()
.setTraceId(traceContext.traceIdString())
.setDescription(description)
.setType(ResultTypeEnum.FAIL.getCode())
.setCreateTime(LocalDateTime.now());
//@formatter:on
log.info("【操作日志error】插入執(zhí)行日志:{}", JSON.toJSONString(executionLog));
mongoTemplate.insert(executionLog);
} catch (Exception e) {
log.error("【操作日志error】操作失敗", e);
}
}
/**
* 批量新增操作日志
*
* @param executionLogDtoList
* 批量的操作日志
*/
@Override
public void batchLog(List<ExecutionLogDto> executionLogDtoList) {
try {
TraceContext traceContext = tracing.currentTraceContext().get();
if (traceContext == null) {
log.error("【批量新增操作日志】沒有traceId");
return;
}
//@formatter:off
List<ExecutionLog> executionLogList = executionLogDtoList.stream().map(dto -> new ExecutionLog().setTraceId(traceContext.traceIdString())
.setType(dto.getType())
.setDescription(dto.getDescription())
.setCreateTime(LocalDateTime.now())).collect(Collectors.toList());
//@formatter:on
if (log.isDebugEnabled()) {
log.debug("【批量新增操作日志】批量插入執(zhí)行日志:{}", JSON.toJSONString(executionLogList));
}
mongoTemplate.insertAll(executionLogList);
} catch (Exception e) {
log.error("【批量新增操作日志】操作失敗", e);
}
}
/**
* 查詢操作日志
*
* @param traceId
* 鏈路id
* @return
*/
@Override
public OperateLogDto findOperateLog(String traceId) {
// 查詢操作記錄
OperateRecord operateRecord = mongoTemplate
.findOne(new Query(Criteria.where(OperateRecordConstant.TRACE_ID).is(traceId)), OperateRecord.class);
if (operateRecord == null) {
return null;
}
// 操作日志
List<ExecutionLog> executionLogList = mongoTemplate
.find(new Query(Criteria.where(ExecutionLogConstant.TRACE_ID).is(traceId)), ExecutionLog.class);
// 構建操作記錄返回值
OperateLogDto operateLogDto = new OperateLogDto().buildOperateLogDto(operateRecord).setExecutionLogs(
executionLogList.stream().map(OperateLogDto.ExecutionLogDto::new).collect(Collectors.toList()));
log.info("查看操作記錄日志:{},traceId:{}", JSON.toJSONString(operateLogDto), traceId);
return operateLogDto;
}
/**
* 生成新的traceId
*
* @return
*/
@Override
@NewSpan
public String newTraceId() {
TraceContext traceContext = tracing.currentTraceContext().get();
String traceId = traceContext.traceIdString();
log.info("生成新的traceId:{}", traceId);
return traceId;
}
}
具體業(yè)務代碼實現(xiàn)：
菜單批量綁定商品接口請求入口使用線程池是為解決接口運行超過網(wǎng)關所設超時問題
public class ProductPolicyController {
@Autowired
private ProductPolicyService productPolicyService;
@Autowired
@Qualifier("commonTraceableExecutor")
private ExecutorService commonExecutorService;
@Autowired
private LogManager logManager;
@PostMapping("/batch-binding")
@ApiOperation("菜單批量綁定商品")
public BaseResult batchBindingProducts(@Validated @RequestBody BatchBindingProductForm productForm) {
log.info("菜單批量綁定商品入?yún)ⅲ簆roductForm:[{}]", JSON.toJSON(productForm));
//記錄一條操作日志后持际，直接異步調(diào)用業(yè)務方法，給前端返回一個接口請求成功哗咆，目的是防止接口執(zhí)行時間過長導致網(wǎng)關斷開連接
logManager.begin(ExecuteTypeEnum.BATCH_INSERT.getCode());
commonExecutorService.execute(()->{
productPolicyService.batchBindingProducts(productForm);
});
return BaseResult.success();
}
}
sleuth線程池配置
@Configuration
public class ExecutorConfig {
@Autowired
private ApplicationContext applicationContext;
private ThreadPoolExecutor policyPoolExecutor =
new ThreadPoolExecutor(10, 20, 60, TimeUnit.SECONDS,
new LinkedBlockingQueue<>(100000));
private ThreadPoolExecutor mtPoolExecutor =
new ThreadPoolExecutor(30, 30, 60, TimeUnit.SECONDS,
new LinkedBlockingQueue<>(100000));
/**
*供后臺操作異步使用Ｖ┯！晌柬！
*/
private ThreadPoolExecutor commonPoolExecutor =
new ThreadPoolExecutor(10, 10, 60, TimeUnit.SECONDS,
new LinkedBlockingQueue<>(100000));
/**
*供后臺操作異步使用＠逊荨！年碘！
*/
@Bean(value = "commonTraceableExecutor")
public ExecutorService commonExecutorService(){
return new TraceableExecutorService(applicationContext, commonPoolExecutor);
}
/**
* 后臺菜單線程池
*/
@Bean(value = "policyTraceableExecutor")
public ExecutorService policyExecutorService(){
return new TraceableExecutorService(applicationContext, policyPoolExecutor);
}
}
public void batchBindingProducts(BatchBindingProductForm productForm) {
//......
final CountDownLatch latch = new CountDownLatch(policyIds.size());
for (Policy policy : policies) {
traceableExecutorService.execute(() -> {
try {
//......
logManager.success(policy.getId() + "-【" + policy.getName() + "】批量添加商品成功");
log.info("批量添加商品成功 policy:[{}], products:[{}]", policy.getId(), newProductIds);
} catch (Exception e) {
log.error("批量添加商品成功 policy:[{}], productForm:[{}]", policy.getId(), JSON.toJSON(productForm));
logManager.error(policy.getId() + "-【" + policy.getName() + "】批量添加商品失敗");
}finally {
latch.countDown();
}
});
}
try {
latch.await();
} catch (Exception e) {
log.error("批量添加商品失敗 productForm:[{}]", JSON.toJSON(productForm));
logManager.error("批量添加商品失敗");
}
log.info("批量添加商品成功 productForm:[{}]", JSON.toJSON(productForm));
logManager.end();
}
由于記錄了每次請求執(zhí)行結(jié)果以及執(zhí)行過程詳細日志澈歉，前端就可以實現(xiàn)長輪詢來給用戶提供請求執(zhí)行進度，或提供一個專門的頁面讓運營來查詢進度
二屿衅、后續(xù)優(yōu)化方向
新增異常告警系統(tǒng)埃难，為什么新增異常監(jiān)控系統(tǒng)，舉個例子：前端-->A服務-->B服務-->C服務涤久，我們現(xiàn)在的處理方式是把traceId返回給前端涡尘，異常時前端或運維會直接找到A服務的負責人，這時A服務負責人會很快的拿traceId查找問題响迂，發(fā)現(xiàn)不是自己負責服務問題考抄，接著找下游服務的負責人，這樣一個問題可能需要按服務調(diào)用先后依次全部排查蔗彤，定位問題效率就非常低川梅。
異常告警系統(tǒng)功能：
約定收集信息模板疯兼，比如規(guī)定必填字段：異常服務名，服務報異常事件挑势，生成一個全局唯一ID镇防，非必填字段：traceId，用戶id等
定位告警策略：定義每個服務的告警策略，比如告警次數(shù)、告警方式（短信饲宿、或郵件提醒）等
三乖仇、總結(jié)
各種原因，日志優(yōu)化穿插在不同版本業(yè)務開發(fā)迭代中类缤，以上優(yōu)化使日志級別分類更清晰，告警日志更明確，給請求鏈路加上traceId扑毡，在解決traceId線程穿透問題的同時，把耗時超過10秒的各種批量發(fā)布問題導致前端報請求超時問題解決了（有更優(yōu)的方案盛险，歡迎一起導論）瞄摊，歡迎各位大佬分享自己的干貨。
