日志规范 V1.0
适用范围:适用于通用服务日志(如nginx/redis/mysql日志)之外的所有线上落盘日志,包括服务端业务日志,BI日志,移动端APP日志。
实施范围:要求所有新业务模块以及深度重构的模块实施日志规范,鼓励现有业务模块通过日志组件替换或改造来实施标准日志规范
主要设计思路与折衷:
- 引入数据标签DLTAG,便于日志分类与提取
- 日志内容使用格式化key/value,实现日志特定字段与数据的统一化解析
- 日志格式与BI日志保持兼容(双竖线分隔),实现所有业务日志规范的统一,同时最大程度降低BI日志及处理系统改造的成本
- 引入默认DLTAG(_undef)与默认key(_msg=)机制,无缝兼容老日志改造,降低非结构化业务日志的研发成本
- 引入Trace技术,融入日志规范要求,实现请求数据的跨服务自动关联,基于日志数据分析进行系统拓扑刻画
一、 日志基本要求
l 日志基础分类
- FATAL: 严重错误日志,若出现则代表模块需要退出,或者出现重大运行错误
- **[可选]**ERROR:普通错误日志,请求处理中出现非预期错误,但模块可以继续服务无需退出
- WARNING: 警告日志
- [可选] STRACE:引入特定日志级别, 记录trace信息同时配合采样逻辑。 放在warning和info日志等级间
- INFO(NOTICE): 系统通知日志,不包括单个请求的处理日志,例如系统的启动、停止、词表配置重载
- TRACE: 请求跟踪日志,只包括单个请求的处理和通知日志,例如请求的入口、出口、外部调用
- DEBUG: 代码调试日志
l 日志存储与拆分
- 当前写入的日志名必须固定,不允许增加变化的前缀或者后缀
- 日志可以根据量级按小时或者按天切分,切分格式建议追加时间后缀,如didi.log.2015122310
- 同类日志在所有机器上的部署路径必须保持一致
- 线上服务不允许开启DEBUG级别日志
- [可选] 日志文件以模块名为前缀,以"."分隔
- 错误日志以独立文件存储,建议拆分为:
- 模块名.log:记录INFO/TRACE/DEBUG日志
- 模块名.log.wf:记录FATAL/ERROR/WARNING日志
l 日志内容基础要求
- 单条日志不允许跨多行(Java和Python的异常信息除外)
- 单条日志最大长度不超过4096(待讨论确定),否则需要截断
- 日志中所有功能字符必须为英文字符,例如冒号、分号、逗号等
- 单条日志必须包含时间字段,建议精确到毫秒,带有时区,格式要求为: yyyy-MM-ddTHH:mm:ss.SSSZ,如"2015-12-23T15:19:25.089+0800"
l 不允许记录的日志
- 数据库:除数据库名外的所有连接信息。例数据库IP、数据库用户名、数据库密码
- 用户:除用户UID、用户名外的所有用户信息。例用户邮箱、用户密码等
- 第三方接口:与第三方接口之间的权限验证等信息。例TOKEN、密钥等
二、 日志格式要求
l 日志内容及格式要求
-
格式示例: [INFO][2015-12-02T00:00:07.099+0800][com/dataapi/handler.DataApi:212] dltag||key1=value1||key2=value2||key3=value3||……
-
格式说明:
-
单条日志分为三个部分:”固定日志头 数据标签DLTAG||KV字段列表“,固定日志头和DLTAG之间用空格( )进行区分、DLTAG和KV列表之间用**双竖线(||)**分隔
-
固定日志头必须包括三个域:[日志级别][时间戳][扩展区域] ,且各个域中不允许出现空格
- 日志级别包括FATAL,WARNING,STRACE,NOTICE,TRACE,DEBUG
- 时间戳格式要求:yyyy-MM-ddTHH:mm:ss.SSSZ 带有毫秒,带有时区,日期与时间通过字母T分隔(eg: 2015-12-02T00:00:07.099+0800)
- 扩展区域用户可以自行定义,大部分场景用来打印”代码行/类名/函数名“,建议的内部格式为: 全路径文件名:行号:类名:函数名(不做细节要求)。
-
数据标签DLTAG用来标识该条日志记录的内容以及日志中能获得的字段信息,与BI日志中的public前缀功能相同,一些重要内容摘要如下:
- 业务日志(非BI日志)中的DLTAG必须以下划线(_)为前缀,目的是为了与BI日志的数据标签做区分,防止重复
- 公司级的DLTAG统一使用_com_为前缀,例如_com_request_in, _com_request_out, _com_http_success
- 每个事业部可以设置自己的DLTAG用来做记录业务相关annotation
- 每个DLTAG都需要有必选和可选的key列表以及value类型描述,
- DLTAG的默认值为_undef,没有具体含义的日志或者无需定义专门DLTAG的日志可以使用默认值
-
KV字段列表
中包含结构化的key与value数据
- 各个key/value组合以双竖线(||)分隔
- key与value之间使用等号(=)链接
- key/value的字段内容中需要避免出现双竖线,key的内容中需要避免出现等号,如果出现,可以通过日志组件进行自动转义
- key的默认值为_msg,没有具体含义的key可以使用默认值,一般搭配_undef的数据标签使用
-
-
目前抽取的公共DLTAG列表,要求所有模块必须输出这些日志
含义 | DLTAG | 基础必选项(注:不可缺少,必打出的key) | 建议可选key | 备注 |
---|---|---|---|---|
请求入口 | _com_request_in | traceid spanid uri (当前接口) | args | callee的access日志①建议使用uri表达接口名称 |
请求出口 | _com_request_out | traceid spanid uri (当前接口)proc_timeerrno | responseerrmsg | callee的access日志①proc_time建议缺省单位s,并且缺省单位。 如果不是建议方式,至少需要在一个模块内部保持一致。②建议使用uri表达接口名称 |
请求外部thrift接口 | _com_thrift_success/failure | traceid spanid cspanid uri (当前接口)interface (下游接口)proc_timeerrno | host(远程请求地址)porterrmsg | caller的调用外部thrift接口的日志,一般在请求拿到response后记录 |
请求外部http接口 | _com_http_success/failure | traceidspanidcspaniduri (当前接口) url (下游接口)proc_timeerrno | host(远程请求地址)porterrmsg | caller的调用外部http接口的日志,一般在请求拿到response后记录 |
请求外部mysql | _com_mysql_success/failure | traceid****spaniduri (当前接口)method_name(select、update等)proc_timeerrno | host(远程请求地址)porttableerrmsg | caller的调用mysql服务的日志,一般在请求拿到response后记录 |
请求外部redis | _com_redis_success/failure | traceid****spaniduri (当前接口)method_name(set、get等)proc_timeerrno | host(远程请求地址)porterrmsg | caller的调用redis服务的日志,一般在请求拿到response后记录 |
远程dubbo请求 | _com_dubbo_success_com_dubbo_failure | traceidspanidcspaniduri (当前接口) url (下游接口) proc_timeerrno | host(远程请求地址)porterrmsg | ①url 表达远程接口②uri 表达当前接口若A—>B则 url =B,uri =A |
其他 | _undef | _msg | traceid****spanid | **① _undef不属于 _com型通用dltag② 需要与 _com型通用日志配合使用,并且正确使用traceid spanid,来记录系统行为。 ** |
l 日志兼容问题
-
业务日志中会有很多无需kv化的日志,多数只输出一个message,对于此类日志可以使用默认DLTAG和key来进行兼容,
默认DLTAG=_undef。默认key为_msg
:
- 调整前: [INFO] [2015-12-02 00:00:07.099+0800][com/dataapi/handler.DataApi:212] params error. fail over
- 调整后: [INFO] [2015-12-02 00:00:07.099+0800][com/dataapi/handler.DataApi:212] _undef||_msg=params error. fail over
- 注意:日志格式调整可能会涉及到依赖日志的应用(比如odin监控规则)的调整。
-
老模块改造中,兼容旧的日志打印接口:新的日志组件可以保留老的接口,即允许用户不传入DLTAG,仍然只传入一个msg,但新日志组件会自动将日志打印为如下格式:
- [INFO] [2015-12-02 00:00:07.099+0800][com/dataapi/handler.DataApi:212] _undef||_msg=params error. fail over
三、 trace相关信息
l trace信息
日志记录同时记录相关的trace信息。用来串联跨模块请求的日志。
-
引入traceid
,用来唯一描述一次端到端的请求访问。需要业务代码配合进行trace信息的生成,解出,传递,记录。
- 生成:在APP端上或者nginx服务器生成的uuid。
- 解出:在请求进入的时候将请求中的traceid解出。
- 传递:在访问外部http,thrift等网络通信请求的时候将traceid植入在请求中传递。
- 记录:在请求入口,请求出口,访问外部http,thrift等网络通信请求的时候将traceid记录进入日志。(或者任意一条业务日志记录的时候都将traceid记录)
-
引入spanid,cspanid(childSpanid)
。 用来描述一个请求访问(一个trace)在一个模块内部的唯一标示(一个span)。需要业务代码配合进行span信息的生成,解出,传递,记录。
– 以下的解释站在callee的角度来描述了,请细细体会
- 生成:每个模块被调用方指定spanid(如果没有则生成一个spanid)
- 解出:在请求进入的时候将请求中的cspanid解出,作为自己的spanid。
- 传递:在访问外部http,thrift等网络请求的时候,生成cspanid,将cspanid植入在请求中传递。
- 记录:在请求入口,请求出口记录spanid;访问外部http,thrift等网络通信请求的时候将spanid,cspanid记录进入日志。
-
依据语言特性,php,java的日志组件(保存在TLS里面)可以自动在日志中加入traceid和spanid。其他语言日志组件需要显示传入
-
一个带有trace信息的日志:
[NOTICE][2016-03-28T12:29:20.999+0800][line=/home/xiaoju/webroot/gulfstream/application/pay/v1/helpers/log_helper.php +442 class=? function=::log_request] _com_request_in||traceid=0af289a156f8b3200e6f5344345e7e02||spanid=f4b6a0ec58a4f503||cspanid=5df56b99411f4fab||logid=408994954500||uri=/gulfstream/pay/v1/wxpayinterface/jsSDKSign||url=/gulfstream/pay/v1/wxpayinterface/jsSDKSign||from=10.242.154.79
用一个图来说明一下dltag,traceid,spanid和cspanid在trace链条串联的作用。
这是跨模块调用的trace信息传递的图。
这几条格式化日志是在一次具体的调用中,接口dPullOrder调用接口getDriverInfo产生的日志中的几个字段。
①红框内,属于同一个traceid(0af2a17358346a0627fd437e199dd102)。整个调用输入一个调用栈产生的日志信息,traceid在这个调用栈的请求内透传。
②黄框内,是该调用(trace)在模块1(dPullOrder)产生的所有日志,属于一个spanid(62541ca1663d0b9d)。在模块1处理这个调用中spanid保持一致。
③篮框内,是该调用(trace)在模块2(getDriverInfo)产生的所有日志,属于同一个spanid(6254ecd55a2c05d2)。在模块2处理这个调用中spanid保持一致。
同时模块1(dPullOrder)调用模块2(getDriverInfo)的时候,产生日志将两个spanid关联在一起,构建成62541ca1663d0b9d->6254ecd55a2c05d2的调用关系。
④绿框内,是该调用在模块1产生的业务标注日志(可能是错误异常或者业务打点)。trace聚合会将他们聚合在一起。
l 收益
- 系统整体关联图的自动生成
- 监控与定位
- 单请求功能Trace能力:可以索引任何请求相关联的上下游模块处理、外部服务调用,协助提供一个请求在各个模块的处理信息、快速查找错误日志
- 单请求性能Trace能力:可以生成任意请求在各个调用链模块的耗时信息,快速定位性能瓶颈模块
- 接口稳定性DrillDown能力:一个接口出现不稳定情况,可以进行关联服务的DrillDown分析,自动分析关联的下游接口与外部服务稳定性
- 系统容量预估与监控
- 架构风险、性能分析
四、 [可选] 风险分析
风险分析日志规范如下:
key | 含义 |
---|---|
dltag | _com_http_success、_com_http_failure、_com_thrift_success、_com_thrift_failure |
traceid | traceid |
caller_func | 调用方接口 |
callee_func | 被调用方接口 |
proc_time | 请求耗时 |
errno | 错误码 |
errmsg | 错误信息 |
callee_host | 被调用方ip |
示例:
[NOTICE][2018-04-17T11:49:28.285+0800][line=/home/xiaoju/webroot/gulfstream/application/driver/v2/vendor/disf/spl/src/Trace/Trace.php +641 class=“Disf”\SPL\Trace function=Disf\SPL\Trace::afterRpcHook]
_com_http_success||traceid=xxxxxxxxxxxxxxxxxx||caller_func=/xxxxx/xxxxxxxxxxxxx||callee_func=http://xxx.xxx.xxx.xxx:xxxx/xxx/xxxxxxx||errno=0||errmsg=xxx||proc_time=169||callee_host=xxx.xxx.xxx.xxx
日志样例
[INFO][2023-11-06T19:30:03.457+0800][com.xiaoju.manhattan.pay.controller.cashier.OrderController:248] _undef||spanid=004180007c4adef8||traceid=0aa2ff086548ce38a27c3d2343c6f286||_msg=收银台查询订单,queryOrderRespDTO:{"bankName":"农业银行","bankNo":"622848*********5610","bizCode":"","bizMsg":"","closeTime":"2023-11-07 17:37:30","createTime":"2023-11-06 17:37:30","failCode":"","failReason":"","merchantId":"M0002182","orderAmount":23580,"orderNo":"DD0004308020231103155626Uebfag","orderStatus":0,"payAmount":23580,"payChannel":0,"payId":"23110617373000021820c42ae9183qfX","payInfos":[{"bizCode":"","bizMsg":"","failCode":"","failReason":"","payAmount":23580,"payChannel":0,"payElement":"{\"cardNo\":\"uqfn7X*********uzg6/IL8usBwBw4EQ/HUVtP1SM44=\"}","payMethod":200,"status":0}],"payStatus":0,"pmCode":"200","productType":"CASHIER_PAY"}
实现思路
应用程序改造
@Component
@Slf4j
public class AccessFilter implements Filter {@Overridepublic void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {ResponseWrapper responseWrapper = new ResponseWrapper((HttpServletResponse)response);RequestWrapper requestWrapper = new RequestWrapper((HttpServletRequest) request);// 获取请求路径String path = requestWrapper.getRequestURI();String traceId = requestWrapper.getHeader(LogTag.traceIdName);String caller = requestWrapper.getHeader(LogTag.caller_func);if(traceId == null) {traceId = UUID.randomUUID().toString().replace("-","");}MDC.put(LogTag.caller_func,caller);MDC.put(LogTag.callee_func,path);MDC.put(LogTag.traceIdName,traceId);MDC.put(LogTag.spanIdName, UUID.randomUUID().toString().replace("-","").substring(0,25));long startTime = System.currentTimeMillis();MDC.put(LogTag.dltag,LogTag._com_request_in);log.info(requestWrapper.getRequestBody());try {MDC.put(LogTag.dltag,LogTag._undef);chain.doFilter(requestWrapper, responseWrapper);} finally {String content = new String(responseWrapper.getResponseData(), "utf-8");ResultMsg resultMsg = JSON.parseObject(content, ResultMsg.class);long endTime = System.currentTimeMillis();MDC.put(LogTag.proc_time,Long.toString(endTime - startTime));MDC.put(LogTag.errno,Integer.toString(resultMsg.getErrorCode()));MDC.put(LogTag.errmsg,resultMsg.getErrorMsg());MDC.put(LogTag.dltag,LogTag._com_request_out);log.info(content);MDC.clear();response.getWriter().write(content);}}private static class MyPrintWriter extends PrintWriter {public MyPrintWriter(Writer out) {super(out);}@Overridepublic String toString() {return super.out.toString();}}
}
/**
自定义实现日志插件* @author weijinhao* @date 2023/11/18 22:01*/
@Plugin(name = "Log4jEncodeLayout", category = Node.CATEGORY, elementType = Layout.ELEMENT_TYPE, printObject = true)
public class LogPlugin extends AbstractStringLayout {private String formt = "[level][data][method] [dltag]";private PatternLayout patternLayout;private List<String> logKey;protected LogPlugin(Charset charset,String pattern) {super(charset);patternLayout = PatternLayout.newBuilder().withPattern(pattern).build();logKey = new ArrayList<>();logKey.add(LogTag.traceIdName);logKey.add(LogTag.spanIdName);logKey.add(LogTag.caller_func);logKey.add(LogTag.callee_func);logKey.add(LogTag.errno);logKey.add(LogTag.errmsg);logKey.add(LogTag.proc_time);}protected LogPlugin(Charset aCharset, byte[] header, byte[] footer) {super(aCharset, header, footer);}protected LogPlugin(Configuration config, Charset aCharset, Serializer headerSerializer, Serializer footerSerializer) {super(config, aCharset, headerSerializer, footerSerializer);}@Overridepublic String toSerializable(LogEvent event) {String dltag = LogTag.dltag;StringBuffer log = new StringBuffer();//[%level][%data][%method] %DLTAGfinal StackTraceElement element = event.getSource();String logString = new String(formt);logString = logString.replace("level",event.getLevel().name());Instant instant = Instant.ofEpochMilli(event.getInstant().getEpochMillisecond());logString = logString.replace("data", instant.toString());logString = logString.replace("method",element.toString());ReadOnlyStringMap contextData = event.getContextData();Map<String, String> contextMap = contextData.toMap();String dltagContent = contextMap.get(dltag);if(dltagContent == null) {dltagContent = "_undef";}logString = logString.replace(dltag,dltagContent);log.append(logString);HashMap<String, String> sortMap = new HashMap<>();sortMap.putAll(contextMap);for (String keyName : logKey) {String value = sortMap.get(keyName);String tag = "||" + keyName + "=" + (value == null ? "" : value);log.append(tag);sortMap.remove(keyName);}for (Map.Entry<String, String> entry : sortMap.entrySet()) {if(!StringUtils.equals(dltag,entry.getKey())) {String key = entry.getKey();String value = entry.getValue();String tag = "||" + key + "=" + (value == null ? "" : value);log.append(tag);}}String message = patternLayout.toSerializable(event);log.append("||" + "_msg=" + message );return log.toString();}@PluginFactorypublic static Layout createLayout(@PluginAttribute(value = "pattern") final String pattern,@PluginAttribute(value = "charset") final Charset charset) {return new LogPlugin(charset,pattern);}
}
/*** @author weijinhao* @date 2023/11/18 18:02*/
public class LogTag {public static String dltag = "dltag";public static String traceIdName = "traceId";public static String spanIdName = "spanId";public static String caller_func = "caller_func";public static String callee_func = "callee_func";public static String proc_time = "proc_time";public static String errno = "errno";public static String errmsg = "errmsg";public static String _com_request_in ="_com_request_in";public static String _com_request_out = "_com_request_out";public static String _undef ="_undef";public static String _msg = "_msg";
}
log4j2.xml配置
<?xml version="1.0" encoding="UTF-8"?>
<!--packages 参数指定插件包路径,多个路径用逗号隔开-->
<Configuration status="INFO" name="XMLConfigTest" package="com.log.demo.common.log"><Properties><Property name="PATTERN">%m%n</Property><property name="MODULE_NAME">demo</property><property name="LOG_HOME">/home/xiaoju/logs</property></Properties><Appenders><Console name="STDOUT"><Log4jEncodeLayout pattern="${PATTERN}" charset="UTF-8"/></Console><RollingFile name="ROLLINGFILE" fileName="${LOG_HOME}/${MODULE_NAME}.log"filePattern="${LOG_HOME}/${MODULE_NAME}-%d{yyyy-MM-dd}-%i.log"><Log4jEncodeLayout pattern="${PATTERN}" charset="UTF-8"/><Policies><TimeBasedTriggeringPolicy modulate="true"interval="24" /><SizeBasedTriggeringPolicy size="100MB"/></Policies><DefaultRolloverStrategy max="100"><Delete basePath="${LOG_HOME}" maxDepth="3"><IfFileName glob="*/${MODULE_NAME}-*.log"/><IfLastModified age="30d"/> <!-- 这里保留30天 --></Delete></DefaultRolloverStrategy></RollingFile></Appenders><Loggers><Root level="INFO"><AppenderRef ref="STDOUT"/><AppenderRef ref="ROLLINGFILE"/></Root><Logger name="com.snbc.vems" level="INFO" additivity="false"><AppenderRef ref="STDOUT"/><AppenderRef ref="ROLLINGFILE"/></Logger><Logger name="org.apache" level="WARN" additivity="false" includeLocation="false"><AppenderRef ref="STDOUT"/><AppenderRef ref="ROLLINGFILE"/></Logger><Logger name="org.mybatis" level="WARN" additivity="false" includeLocation="false"><AppenderRef ref="STDOUT"/><AppenderRef ref="ROLLINGFILE"/></Logger><Logger name="org.hibernate" level="WARN" additivity="false" includeLocation="false"><AppenderRef ref="STDOUT"/><AppenderRef ref="ROLLINGFILE"/></Logger><Logger name="org.springframework" level="WARN" additivity="false" includeLocation="false"><AppenderRef ref="STDOUT"/><AppenderRef ref="ROLLINGFILE"/></Logger></Loggers>
</Configuration>
项目git地址: https://gitee.com/weijinhao/log.git
上面我们有了日志的具体格式了,我们通过代码也实现了该日志格式。
之后我们就需要使用logstash对日志进行处理,之后输出到es中供我们监控.
logstash 的学习思路主要有一下几点
- logstash 中使用的数据类型 参见:[Structure of a Config File | Logstash Reference 6.1] | Elastic
- logstash 中使用的条件表达是 参见: [Accessing Event Data and Fields in the Configuration | Logstash Reference 6.1] | Elastic
- 然后就是 logstash 的input 输入,我们调试可以使用 stdin标准输入
- 在之后就是filter,比较常用的filter有dissect(分隔符) grovk(正则表达式) date(日期类型转化) mutate(类型或字段修改),等几种表达式
- 最后就是输出了,比如es 的 ,我们调试就使用 stdout 就好了
logstash 的pipeline 配置
# The # character at the beginning of a line indicates a comment. Use
# comments to describe your configuration.
input {#stdin {}file {path => "/home/xiaoju/logs/**/*"sincedb_path => "/home/xiaoju/logstash/logstash-6.1.1/data/log1"start_position => "beginning"codec => multiline {pattern => "^\["charset => "UTF-8"what => "previous"negate => true}}
}
# The filter part of this file is commented out to indicate that it is
# optional.
#[INFO][2023-11-20T09:50:44.872Z][com.log.demo.filter.AccessFilter.doFilter(AccessFilter.java:47)] [_com_request_in]||traceId=a9d350051e834dd58fc0288caf920365||spanId=dcc4e8d0058143e9a898d29ed||callee_func=/test||caller_func=||_msg={
# [INFO][2023-11-20T09:50:44.349Z][com.log.demo.filter.AccessFilter.doFilter(AccessFilter.java:59)] [_com_request_out]||traceId=dbba05f9f404450f927f150f45ac8bc7||spanId=5102773f6c884d95800dbc122||errno=10000||caller_func=||callee_func=/test||errmsg##=success||proc_time=153||_msg={"errorCode":10000,"errorMsg":"success","bizContent":null}filter {dissect {mapping => {"message" => "[%{level}][%{data}][%{}] [%{action}]||traceId=%{traceId}||spanId=%{spanId}||caller_func=%{caller_func}||callee_func=%{callee_func}||errno=%{errno}||errmsg=%{errmsg}||proc_time=%{proc_time}||%{}"}}date {match => [ "data", "ISO8601" ]}mutate {convert => { "errno" => "integer""proc_time" => "integer" }}}output {#stdout {# codec => rubydebug#}elasticsearch {hosts => ["192.168.88.102:9200","192.168.88.103:9200"]index => "goslin-gateway-log"}
}
这之后我们的数据就到了es中了,那我们就可以建立虚拟图,之后建立disboard了,当然需要具备一些 es聚合分析相关的语法才能更好的创建图表.