JStack-CWAP框架日志输出规范
2018-08-29 本文已影响148人
李戬plutocracy
日志输出的方法
好的日志是别人在不必分析具体的代码执行逻辑的情况下可以读懂你要说明的信息；创造性的日志可以反映代码的业务逻辑；之所以要站在上帝的视角编写日志是因为绝大多数时候排查问题的不是你自己
输出日志的时候必须用占位符{} 传入参数，不可以用+符号拼接字符串，这样可以10倍提升日志输出性能。对序列化耗时的日志，前面需要加if（logger.isDebugEnabled）判断。
//在类的开始出声明，一般禁止继承父类或者接口的日志器，除非针对模型有特殊的日志输出设计
private static final TsLogger logger = TsLogger.getLogger(QdbsRest.class);
在关键点输出INFO级别日志（任务的接口、执行结束点或者关键业务分支点）
从DSP、DEP或者Ultra接口接收和发送消息的日志必须是INFO级别，必须有日志输出
public class IndctvQuoteReportNDMHandler implements IMessageUnitHandler, DataValidator<NdmQuoteCbt> {
private static final TsLogger logger = TsLogger.getLogger(IndctvQuoteReportNDMHandler.class);
@Override
public void handle(MessageUnit msg) {
logger.info(" 意向报价信息已接收{}", CommonUtils.objToJson(msg));
if (msg == null) {
throw new InvalidDataException("意向报价报告信息体为null");
}
Object o = msg.getBody();
if (o == null) {
throw new InvalidDataException("报价消息体为空");
}
if (!(o instanceof NdmQuoteCbt)) {
throw new InvalidDataException("报价消息体不为cn.com.cfets.data.msg.ndm.cbt.NdmQuoteCbt，不处理");
}
NdmQuoteCbt qtMsg = (NdmQuoteCbt) o;
String qtCd = null;
if (qtMsg.isSetQuoteBase() && qtMsg.getQuoteBase().isSetQuote()
&& qtMsg.getQuoteBase().getQuote().isSetQtCd()) {
qtCd = qtMsg.getQuoteBase().getQuote().getQtCd();
} else {
throw new InvalidDataException("NDM核心下发的意向报价编号为空");
}
logger.info("[QUOTE HANDLE]意向报价报告信息处理开始{}", qtCd);
QuoteReport<NdmQuoteCbt> quoteReport = new IndicativeQuoteReport(qtCd, qtMsg);
// 通过报价引擎处理意向报价数据
QuoteEngineContext.get().getSpecifiedQuoteEngine(QuoteType.INDICATIVE_QUOTE).addQuote(quoteReport);
}
}
在REST接口中输出日志
@Note(note = "测试权限异常")
@RequestMapping(value = "/test", method = { RequestMethod.GET,
RequestMethod.POST })
@ResponseBody
public SimpleMessage<?> test(HttpServletRequest req, HttpServletResponse rep) {
try {
logger.info("模拟行情");
// 测试行情计算
//......
logger.info("执行行情");
// MarketContext.get().getSummaryCalculator().execute(marketData);
SimpleMessage<?> sm = SimpleMessage.ok().set("market",
marketData.toString());
logger.info("机构会员机构权限列表 ", sm.toJson());
return sm;
} catch (GenericTsRuntimeException e) {
logger.warn("获取机构会员机构权限列表异常", e);
return SimpleMessage.error(
e.getErrorInfo(req.getLocale().toString())).repCode(
e.getErrorCode());
} catch (Exception e) {
logger.warn("获取机构会员机构权限列表异常", e);
return SimpleMessage.error("获取机构会员机构权限列表发生不可知异常");
}
}
在关键的业务逻辑处输出日志
public class PreMarketValidationHandler implements ICleanoutValidationHandler {
private static final TsLogger logger = TsLogger.getLogger(PreMarketValidationHandler.class);
@Override
public boolean validate(MarketAggregateRoot root, CleanoutValidationChain chain) {
logger.info("判断成交报告[{}]是否来自一级半交易", root.getSerialNumber());
if (isActived()) {
if (isOneHalf(root)) {
return false;
} else {
logger.info("[{}]非一级半交易，继续接下来的清洗验证过程",root.getSerialNumber());
return chain.validate(root, chain);
}
} else {
logger.warn("一级半行情验证器未开启");
return chain.validate(root, chain);
}
}
private boolean isOneHalf(MarketAggregateRoot root) {
if ("Y".equals(root.getCbtDealAsset().getPrmrktBondF())) {
logger.info("成交报告[{}]所交易债券是上市前交易债券，该笔交易是一级半交易，不参与成交逐笔和汇总行情计算", root.getSerialNumber());
return true;
}
return false;
}
}
初始化时的关键点
public class DealMarketBooterConfig {
@PostConstruct
void init() {
if (SpiConfig.getPropBooleanValue("tbs.market.auto", false)) {
StringBuilder sb = new StringBuilder();
sb.append("\n===============创建并初始化成交处理全流程引擎=====================\n");
int bufferSize = 2048; // 2的N次方
ThreadFactory threadFactory = new NamedThreadFactory("InjvmEventBus-Executor", false);
sb.append("第1步：感知交易报告已生成事件，执行补全操作\n");
/**
* 交易报告已创建的事件
*/
Disruptor<DealReportCreatedEvent> dealReportCreatedDisruptor = new Disruptor<DealReportCreatedEvent>(
new EventFactory<DealReportCreatedEvent>() {
@Override
public DealReportCreatedEvent newInstance() {
return new DealReportCreatedEvent(); // 交易报告已创建事件
}
}, bufferSize, threadFactory, ProducerType.SINGLE, new BusySpinWaitStrategy());
DealReportToCompleteHandler dealCompletorHandler = new DealReportToCompleteHandler();
/**
* 逐笔成交行情先进行交易补全
*/
dealReportCreatedDisruptor.handleEventsWith(dealCompletorHandler);
sb.append("第2步：感知交易报告已补全事件，兵分两路，一路进行清洗操作，一路不清洗，调用计算构件，直接生成汇总行情，下发DEP\n");
/**
* 逐笔成交行情交易补全之后进行逐笔成交行情生成操作
*/
Disruptor<DealReportCompletedEvent> dealReportCompletedDisruptor = new Disruptor<DealReportCompletedEvent>(
new EventFactory<DealReportCompletedEvent>() {
@Override
public DealReportCompletedEvent newInstance() {
return new DealReportCompletedEvent();
}
}, bufferSize, threadFactory, ProducerType.SINGLE, new BusySpinWaitStrategy());
DealReportToCleanoutHandler dealReportToCleanoutHandler = new DealReportToCleanoutHandler();
// 验证规则
dealReportToCleanoutHandler.addCleanoutHandler(new PreMarketValidationHandler());
dealReportToCleanoutHandler.addCleanoutHandler(new ActivityBondValidationHandler());
dealReportToCleanoutHandler.addCleanoutHandler(new CentralDepositoryValuationValidationHandler());
RawDealMarketDataToCreateEventHandler rawDealMarketDataToCreateEventHandler = new RawDealMarketDataToCreateEventHandler();
/**
* 进入清洗，计算逐笔及汇总
*/
dealReportCompletedDisruptor.handleEventsWith(dealReportToCleanoutHandler);
/**
* 不清洗，计算汇总并下发
*/
dealReportCompletedDisruptor.handleEventsWith(rawDealMarketDataToCreateEventHandler);
sb.append("第3.1步：感知交易报告已清洗事件，兵分两路，一路计算清洗后的逐笔成交行情，并推送DEP和统一终端，一路计算清洗后的汇总成交行情\n");
Disruptor<DealReportCleanedEvent> dealReportCleanedDisruptor = new Disruptor<DealReportCleanedEvent>(
new EventFactory<DealReportCleanedEvent>() {
@Override
public DealReportCleanedEvent newInstance() {
return new DealReportCleanedEvent();
}
}, bufferSize, threadFactory, ProducerType.SINGLE, new BusySpinWaitStrategy());
TickDealDataToCreateAndSendEventHandler tickDealDataToCreateAndSendEventHandler = new TickDealDataToCreateAndSendEventHandler();
tickDealDataToCreateAndSendEventHandler.registerSender(new CbtDealDataCutSender());
tickDealDataToCreateAndSendEventHandler.registerSender(new CbtDealTickMarketDepSender());
tickDealDataToCreateAndSendEventHandler.init();
DealMarketDataToCreateEventHandler dealDataCreatedEventHandler = new DealMarketDataToCreateEventHandler();
/**
* 逐笔成交行情计算和推送
*/
dealReportCleanedDisruptor.handleEventsWith(tickDealDataToCreateAndSendEventHandler);
/**
* 成交行情计算
*/
dealReportCleanedDisruptor.handleEventsWith(dealDataCreatedEventHandler);
sb.append("第3.2步：感知未清洗成交汇总行情已生成事件，推送DEP\n");
Disruptor<RawDealMarketCreatedEvent> rawDealMarketCreatedDisruptor = new Disruptor<RawDealMarketCreatedEvent>(
new EventFactory<RawDealMarketCreatedEvent>() {
@Override
public RawDealMarketCreatedEvent newInstance() {
return new RawDealMarketCreatedEvent();
}
}, bufferSize, threadFactory, ProducerType.SINGLE, new BusySpinWaitStrategy());
RawDealMarketToSendEventHandler rawDealMarketToSendEventHandler = new RawDealMarketToSendEventHandler();
// 未清洗汇总行情推送
rawDealMarketToSendEventHandler.registerSender(new CbtRawDealMarketDepSender());
rawDealMarketToSendEventHandler.init();
rawDealMarketCreatedDisruptor.handleEventsWith(rawDealMarketToSendEventHandler);
sb.append("第4.1.1步：感知汇总成交行情已生成事件，刷新快照，执行扩展路逻辑包括存库\n");
Disruptor<DealMarketCreatedEvent> dealMarketCreatedDisruptor = new Disruptor<DealMarketCreatedEvent>(
new EventFactory<DealMarketCreatedEvent>() {
@Override
public DealMarketCreatedEvent newInstance() {
return new DealMarketCreatedEvent();
}
}, bufferSize, threadFactory, ProducerType.SINGLE, new BusySpinWaitStrategy());
DealMarketDataToSaveEventHandler dealMarketCreatedEventHandler = new DealMarketDataToSaveEventHandler();
/**
* 汇总成交行情交易补全
*/
dealMarketCreatedDisruptor.handleEventsWith(dealMarketCreatedEventHandler);
sb.append("第5.1.1步：感知汇总成交行情已持久化事件，一路调用汇总行情推送处理器推送DEP和CUT,其它路调用气泡图、利率债、信用债、同业存单等计算单元，生成快照\n");
Disruptor<DealMarketSavedEvent> otherDisruptor = new Disruptor<DealMarketSavedEvent>(
new EventFactory<DealMarketSavedEvent>() {
@Override
public DealMarketSavedEvent newInstance() {
return new DealMarketSavedEvent();
}
}, bufferSize, threadFactory, ProducerType.SINGLE, new BusySpinWaitStrategy());
DealMarketDataToSendEventHandler dealMarketDataToSendEventHandler = new DealMarketDataToSendEventHandler();
dealMarketDataToSendEventHandler.registerSender(new CbtMarketDataCutSender());
// 行情推送TOPIC(订阅主题用户需要接收的消息)
dealMarketDataToSendEventHandler.registerSender(new CbtDealDataCutTopicSender());
dealMarketDataToSendEventHandler.registerSender(new CbtMarketDataCutTopicSender());
dealMarketDataToSendEventHandler.registerSender(new CbtMarketTradeSender());
// 分时切片行情推送
dealMarketDataToSendEventHandler.registerSender(new CbtSnapshotMarketDataCutSender());
dealMarketDataToSendEventHandler.init();
InterestRateYieldEventHandler interestRateYieldEventHandler = new InterestRateYieldEventHandler();
InterbankDepositEventHandler interbankDepositEventHandler = new InterbankDepositEventHandler();
BubbleGraphEventHandler bubbleGraphEventHandler = new BubbleGraphEventHandler();
CreditYieldBondEventHandler creditYieldBondEventHandler = new CreditYieldBondEventHandler();
otherDisruptor.handleEventsWith(dealMarketDataToSendEventHandler);// 推送各个维度的成交汇总行情数据
otherDisruptor.handleEventsWith(interestRateYieldEventHandler);// 利率债
otherDisruptor.handleEventsWith(interbankDepositEventHandler);// 同存
otherDisruptor.handleEventsWith(creditYieldBondEventHandler);// 信用债
otherDisruptor.handleEventsWith(bubbleGraphEventHandler);// 气泡图
/**
* 注册Disruptor的Translator
*/
BaseDom.registerHanlder(DealTickMarketCreatedEventTranslator.class, dealReportCreatedDisruptor);
BaseDom.registerHanlder(RawDealMarketCreatedEventTranslator.class, rawDealMarketCreatedDisruptor);
BaseDom.registerHanlder(DealMarketCreatedEventTranslator.class, dealMarketCreatedDisruptor);
BaseDom.registerHanlder(DealCleanOutCreatedEventTranslator.class, dealReportCleanedDisruptor);
BaseDom.registerHanlder(DealCompletedCreatedEventTranslator.class, dealReportCompletedDisruptor);
BaseDom.registerHanlder(DealMarketSavedEventTranslator.class, otherDisruptor);
CbtMarketContext.get().registerDisruptor("dealReportCreatedDisruptor", "现券买卖成交报告已创建后处理单元",
dealReportCreatedDisruptor);
CbtMarketContext.get().registerDisruptor("rawDealMarketCreatedDisruptor", "未清洗的成交汇总行情创建后处理单元",
rawDealMarketCreatedDisruptor);
CbtMarketContext.get().registerDisruptor("dealMarketCreatedDisruptor", "现券买卖汇总成交行情已创建后处理单元",
dealMarketCreatedDisruptor);
CbtMarketContext.get().registerDisruptor("dealReportcleanedDisruptor", "成交报告清洗之后处理单元",
dealReportCleanedDisruptor);
CbtMarketContext.get().registerDisruptor("dealReportCompletedDisruptor", "成交报告补全后处理单元",
dealReportCompletedDisruptor);
CbtMarketContext.get().registerDisruptor("otherDisruptor", "成交汇总行情已保存后处理单元", otherDisruptor);
/**
* 启动所有的disruptor
*/
sb.append("启动各个Disruptor:" + CbtMarketContext.get().getAllDisruptor().toString());
sb.append("\n===============创建并初始化成交处理全流程引擎=====================\n");
logger.info(sb.toString());
CbtMarketContext.get().startAllDisruptor();
logger.info("已启动所有的现券买卖市场行情Disruptor");
} else {
logger.warn("未初始化成交处理全流程引擎");
}
}
}
在核心业务逻辑出输出日志，包括性能日志
public <T> void addQuote(QuoteReport<T> quoteReport) {
try {
long startTime = System.currentTimeMillis();
logger.info("报价报告[{}]开始转为报价明细", quoteReport.getQuoteCode());
// 判断报价报告消息类型
QuoteMessageType msgType = convertor.confirmQuoteMessageType(quoteReport);
quoteReport.setMessageType(msgType);
// 判断报价状态
QuoteStatus quoteStatus = convertor.confirmQuoteStatus(quoteReport);
quoteReport.setQuoteStatus(quoteStatus);
logger.info("报价报告[{}]的消息操作类型为【{}】，报价的最终状态为【{}】", quoteReport.getQuoteCode(), msgType.toString(),
quoteStatus.toString());
// 判断报价报告消息是否合法
boolean isLegal = convertor.isLegal(quoteReport);
if (!isLegal) {
throw new QuoteEngineException("核心系统【" + name + "】发送的报价报告不符合接口规范");
}
long startConvertTime = System.currentTimeMillis();
// 报价报告转为报价明细
QuoteDetail quoteDetail = convertor.convert(quoteReport);
quoteDetail.setMessageType(msgType);
quoteDetail.setQuoteStatus(quoteStatus);
logger.info("报价报告[{}]成功转为报价明细,耗时{}ms", quoteReport.getQuoteCode(),
System.currentTimeMillis() - startConvertTime);
logger.info("报价报告[{}]补全开始", quoteReport.getQuoteCode());
// 调用各种报价的补全逻辑，补全报价明细
long startCompleteTime = System.currentTimeMillis();
QuoteCompletor.CompletedResult result = convertor.callCompletorsAfterConverted(quoteDetail,
(MetaObject) quoteReport.getQuote());
logger.info("报价报告[{}]补全完成{},耗时{}ms", quoteReport.getQuoteCode(), result,
System.currentTimeMillis() - startCompleteTime);
// 调用报价明细处理的扩展逻辑，主要是入库
if (handler != null) {
long startHandleTime = System.currentTimeMillis();
logger.info("报价报告[{}]开始执行扩展业务处理逻辑", quoteReport.getQuoteCode());
handler.handle(result.getCompletedQuoteDetail());
logger.info("报价报告[{}]成功成功执行扩展业务处理逻辑,耗时{}ms", quoteReport.getQuoteCode(),
System.currentTimeMillis() - startHandleTime);
}
// 调用报价明细处理的推送逻辑，主要是根据业务特征推送报价消息到DEP和统一终端
if (sender != null) {
long startSendTime = System.currentTimeMillis();
logger.info("报价报告[{}]开始执行推送业务逻辑处理逻辑", quoteReport.getQuoteCode());
sender.send(result.getCompletedQuoteDetail());
logger.info("报价报告[{}]成功成功执行推送业务处理逻辑,耗时{}ms", quoteReport.getQuoteCode(),
System.currentTimeMillis() - startSendTime);
}
logger.info("报价报告[{}]成功转为报价明细，并执行了全部操作,耗时{}ms", quoteReport.getQuoteCode(),
System.currentTimeMillis() - startTime);
} catch (Exception e) {
logger.error("报价报告[{}]转为报价明细时发生异常", quoteReport.getQuoteCode(), e);
}
}
请尽量用中国人可以读懂的中文语句输出日志，不要用蹩脚的中文短词和不连贯的英文单词表达日志信息，当然如果你的英文水平够优秀，我们没有理由禁止你使用优美的英文语句输出日志信息
总结如下，日志输出可能涉及的关键点：
-
系统启动和创建环境变量，构件模型的初始化时，必须针对性的输出初始化信息，以确认功能是否正常或者符合预期的启动。
-
在业务逻辑存在多种分支逻辑时，在分支逻辑出输出日志，以跟踪代码执行的逻辑。
-
关键操作和业务流程，例如数据库操作、缓存操作、读写文件系统、调用一个定时任务，进行成交或者开闭市等核心业务操作流程输出日志。
-
在接口处输出日志，来划清责任边界。
日志信息要求：
日志信息必须能反映上下文业务内容是什么，当前执行情况，当前问题原因，是否需要开发人员排查，和必要的警示标记，以备监控。
日志输出规范和原则
日志输出考察的是开发人员的最基本功，可惜绝大多数经过了技术训练的开发人员仍然不能很好的输出日志。主要体现在开发人员对日志作用的理解不到位和编程时的心态不正确。因此必须始终保持对编程这份工作的积极心态，不断去思考怎样优化自己编写的代码逻辑。这就要求开发人员必须通过日志反映自己代码执行的各种状况，包括是否走在正确的逻辑中，是否进入了错误的分支逻辑，主要逻辑的执行性能，面对各种执行状态如何改善代码的结构和性能。
日志的打印会影响程序的性能，所以开发人员在写日志的时候必须在有效表达执行逻辑和代码执行性能之间做出平衡，时时刻刻都要尝试去平衡日志和代码的执行效率。
日志是追踪排查问题的主要工具。混乱的日志记录，将会导致开发人员自己或者测试人员无法准确快速的定位问题发生的原因、问题发生的场景，干扰运维人员的视线。
日志输出的目的：
-
问题追踪，优先方便测试人员在测试环境帮助开发人员快速定位问题，其次方便开发人员在开发阶段反映代码的执行逻辑问题。
-
状态监控，通过实时分析日志，可以监控系统的运行状态，尽早暴露危险的执行情况，早发现问题、早处理问题。
-
安全审计，通过对日志进行分析，可以发现是否存在非授权的操作等。
日志级别的意义：
1.ERROR：问题已经影响到软件或业务的正常运行，甚至软件不能自行恢复到正常的运行状态，例如上游核心系统传输的数据缺失必要的信息或者数据库操作的异常。此时需要输出该级别的错误日志。告知运维人员，如果检测到此类错误，需要开发人员现场排查问题。
2.WARN：与业务处理相关的失败，此次失败不影响下次业务的执行，通常的结果为外部的输入不能获得期望的结果，或者程序走到了不应该走到的分支逻辑中，通过警告形式告知运维人员关注此类问题，并适时通知业务和开发人员关注。
3.INFO：系统运行期间的系统运行状态变化，或业务处理的主要逻辑控制点等方便开发人员在系统运行期间关注的一些信息，实际情况下，所有日志阅读者应能从INFO日志中直接理解主要的业务逻辑。
4.DEBUG：一般情况下对于不太重要的需要序列化的日志信息或者过程处理信息，运用DEBUG级别输出日志，并且前置加上布尔判断（isDebugEnabled），提供尽量完整的软件调试信息，和跟踪代码执行的分支逻辑。如果INFO级别的日志不能反映部分问题，开发人员临时开启DEBUG级别的日志排查程序运行中的故障。
日志输出技术介绍
JStack-CWAP框架默认使用log4j2+slf4j+disruptor的技术实现异步输出日志，日志的输出不保证顺序性，这是目前Java开发中最高性能的日志输出技术之一。
请开发人员在业务功能模块开发过程中，使用ts-s-log构件提供的TsLogger接口类输出日志信息;不建议开发人员直接使用slf4j提供的Logger ;禁止开发人员使用log4j提供的Logger 输出日志；禁止开发人员使用e.printStackTrace或者System.out输出日志
在生产环境日志的级别是INFO级别，这就意味着DEBUG级别输出的日志不会打印出来。
ts-s-log构件支持特殊应用场景的日志：
-
定时任务日志输出 TsJobLogger：将关键的定时任务执行状态信息直接记录到数据库中备案监控。
-
关键任务日志输出 TsEventLogger：将关键的异常信息直接记录到数据库中备案监控，例如成交明细生成异常或者基准指标计算异常。
-
操作行为日志输出TsAdminLogger：将场务或者管理人员对系统的所有关键操作直接记录到关系型数据库或者Cassandra中，以备审计。
我们的日志构件对日志的规范使用做了比较细致的体验改进，这也是我们希望你使用TsLogger的原因
ts-u-log构件目前和未来准备支持的应用场景包括：
-
目前已支持日志监控配置和关键异常日志的过滤查询。
-
计划支持基于JAVA的分布式追踪系统Sky Walking的采样监控。
3.目前已支持不重启进程，完成日志级别的主动切换。
