日志格式规范

1 简介

在程序中写日志是一件非常重要，但是很容易被开发人员忽视的地方。写好程序的日志可以帮助我们大大减轻后期维护压力。在实际的工作中，开发人员往往迫于巨大时间压力，而写日志又是一个非常繁琐的事情，往往没有引起足够的重视。

开发人员应在一开始就养成良好的日志撰写习惯，并且应在实际的开发工作中为写日志预留足够的时间。

1.1 日志的作用

一般程序日志出自下面几个方面的需求：

1. 记录用户操作的审计日志，甚至有的时候就是监管部门的要求。
2. 快速定位问题的根源
3. 追踪程序执行的过程。
4. 追踪数据的变化
5. 数据统计和性能分析
6. 采集运行环境数据

一般在程序上线之后，一旦发生异常，第一件事就是要弄清楚当时发生了什么。用户当时做了什么操作，环境有无影响，数据有什么变化，是不是反复发生等，然后再进一步的确定大致是哪个方面的问题。确定是程序的问题之后再交由开发人员去重现、研究、提出解决方案。这时，日志就给我们提供了第一手的资料。

1.2 撰写日志的要求

既然撰写日志是有需求，而且也能在未来帮助我们提高工作效率的事情，长远来看是非常有利的一件事情。因此我们应该在自己开发的程序中符合规范的撰写日志，在写日志时要注意以下的问题。

1.2.1 日志的可读性

日志时给人读的，不仅仅是让自己明白，也要让没有接触过我们源代码的其他程序员也能够一目了然。有的同事在日志中打印特殊的标识符号，例如“++++++++++”， “===========”，“—————”，这些符号令人眼花缭乱。这是一种不好的编程习惯。

另外，把日志分类输出到不同的文件也有利于我们排除干扰，迅速找到我们需要的信息。而且，最好在打印日志时输出英文，防止中文不支持而打印出乱码的情况。

1.2.2 日志的性能

无论我们把日志写到文件还是数据库，都需要消耗IO资源。适当的控制日志的输出也有利于提高程序的性能。

例如：尽量避免在在大的循环中打印意义不大的日志内容。输出日志之前最好能判断日志的级别(例如. debug前先调用isDebugEnabled()作出判断)。

1.2.3 占用磁盘空间

通常，我们都是把日志写入磁盘上的日志文件中。适当的使用滚动日志并且定时清除旧文件是有好处的。我见过这样一个例子，程序运行几次后就跑不起来了，前几次都是正常的。

怎么都想不明白程序有什么问题，最后才发现居然是日志文件占满了磁盘空间。在实际的应用中出现上G的日志文件也往往不少见，要在这样规模的日志文件中找出对解决问题有用的信息也是一大挑战。

1.2.4 日志的时效性

有的时候我们并不能及时的发现问题。需要追溯之前的日志。所以我们是需要保留一段时间以内的日志便于追溯。

1.2.5 日志级别

通常我们在产品环境中日志的级别都在INFO以上，所以我们必须保证在这样的情况下程序仍然能够输出足够我们作出判断的信息。

例如常见的系统具有如下的日志级别：

// 定义FATAL级别输出宏
#define DRV_LOG_FATAL(fmt, ...)           hlog_format(HLOG_LEVEL_FATAL, "PluginDriver",   "[%s(%d)] "fmt, __FUNCTION__,   __LINE__, ##__VA_ARGS__)

// 定义ERROR级别输出宏
#define DRV_LOG_ERROR(fmt, ...)           hlog_format(HLOG_LEVEL_ERROR, "PluginDriver",   "[%s(%d)] "fmt, __FUNCTION__,   __LINE__, ##__VA_ARGS__)

// 定义WARN级别输出宏
#define DRV_LOG_WARN(fmt, ...)          hlog_format(HLOG_LEVEL_WARN, "PluginDriver",   "[%s(%d)] "fmt, __FUNCTION__,   __LINE__, ##__VA_ARGS__)  

// 定义INFO级别输出宏
#define DRV_LOG_INFO(fmt, ...)          hlog_format(HLOG_LEVEL_INFO, "PluginDriver",   "[%s(%d)] "fmt, __FUNCTION__,   __LINE__, ##__VA_ARGS__)  

// 定义DEBUG级别输出宏
#define DRV_LOG_DEBUG(fmt, ...)           hlog_format(HLOG_LEVEL_DEBUG, "PluginDriver",   "[%s(%d)] "fmt, __FUNCTION__,   __LINE__, ##__VA_ARGS__)   
// 定义TRACE级别输出宏
#define DRV_LOG_TRACE(fmt,   ...)         hlog_format(HLOG_LEVEL_TRACE, "PluginDriver",   "[%s(%d)] "fmt, __FUNCTION__,   __LINE__, ##__VA_ARGS__)  

上述的日志文件中定义了6种日志级别，不同级别的含义在下文详述，需要了解到在一个程序开发的过程中需要维护不同的分别为FATAL， ERROR， EARN， INFO， DEBUG， TRACE。

1.2.6 日志内容

我们在写日志的时候，需要注意输出适当的内容。首先，尽量使用业务相关的描述。我们的程序是实现某种业务的，那么就最好能描述清楚这个时候走到了业务过程的哪一步。

其次，避免在日志中输出一些敏感信息，例如用户名和密码。以及，要保持编码的一致。如果不能保证就尽量使用英文而不是中文。这样当我们拿到日志之后就不会因为看到一堆乱码而不知所云了。

1.2.7 日志格式

常见的日志格式中对于每一条日志应含有的信息包括日期、时间、日志级别、代码位置、日志内容、错误码等信息。

下面是一个工作中的日志文件的一部分内容：

2018-05-22 15:35:53.850 TRACE TDWZLog [0x00001b10] <36> <TDWZProtocol::Init>,TDWZProtocol::Init
2018-05-22 15:35:53.850 TRACE TDWZLog [0x00001b10] <89> <TDWZProtocol::Init>,End in processing TDWZProtocol::Init
2018-05-22 15:35:53.853 TRACE TDWZLog [0x00001b10] <142>    <TDWZProtocol::Connect>,Connect Execute finish
2018-05-22 15:35:53.853 TRACE TDWZLog [0x00002f10] <149>    <GetAlarmEventPro>,Enter GetAlarmEventPro func
2018-05-22 15:39:36.382 WARN TrackLog [0x000029fc] - [ internal WARN htrace_server_convert_msgstring_to_contextintls(493) ] detect input id error, trace_id span_id,this chain may not be tracked.
2018-05-22 15:39:36.383 WARN TrackLog [0x000029fc] - [ internal WARN htrace_server_receive(195) ] can not detect trace_id in context, this chain may not be tracked.
2018-05-22 15:39:36.383 TRACE TDWZLog [0x000029fc] <231>    <TDWZProtocol::DisConnect>,TDWZProtocol::DisConnect
2018-05-22 15:39:37.502 TRACE TDWZLog [0x00002f10] <225>    <GetAlarmEventPro>,End Get AlarmEventPro Func
2018-05-22 15:39:37.503 TRACE TDWZLog [0x000029fc] <241>    <TDWZProtocol::DisConnect>,close socket
2018-05-22 15:39:37.503 TRACE TDWZLog [0x000029fc] <242>    <TDWZProtocol::DisConnect>,Execute DisConnect function succeed.

可以从该文件中看出一般日志文件中应该含有的信息。

2 日志级别和含义

Log4j是Apache的一个开源项目，通过使用Log4j，我们可以控制日志信息输出目的地是控制台、文件、GUI组件甚至是套接口服务器；我们也可以控制每一条日志的输出格式；通过定义每一条日志信息的级别，我们能够更加细致地控制日志的生成过程。

最令人感兴趣的就是，这些可以通过一个配置文件来灵活地进行配置，而不需要修改应用的代码。

2.1 Log4j的组成

Log4j由三个重要的组成构成：日志记录器(Loggers)，输出端(Appenders)和日志格式化器(Layout)。

2.1.1 Logger

控制要启用或禁用哪些日志记录语句，并对日志信息进行级别限制

2.1.2 Appenders

指定了日志将打印到控制台还是文件中.

2.1.3 Layout

控制日志信息的显示格式。

2.2 日志级别

Log4j中将要输出的Log信息定义了6种级别，依次为TRACE、DEBUG、INFO、WARN、ERROR和FATAL，当输出时，只有级别高过配置中规定的 级别的信息才能真正的输出，这样就很方便的来配置不同情况下要输出的内容，而不需要更改代码，非常方便快捷。

2.2.1 TRACE

TRACE designates finer-grained informational events than the DEBUG.Since:1.2.12，很低的日志级别，一般不会使用。TRACE一般跟踪的是函数的调用，并且TRACE不应该含有变量参数，而仅能提示函数的调用关系。

2.2.2 DEBUG

一般用于细粒度级别上，对调试应用程序非常有帮助，主要用于开发过程中打印一些运行信息。

2.2.3 INFO

INFO消息在粗粒度级别上突出强调应用程序的运行过程。打印一些你感兴趣的或者重要的信息，这个可以用于生产环境中输出程序运行的一些重要信息，但是不能滥用，避免打印过多的日志。

2.2.4 WARN

WARN表示会出现潜在错误的情形，有些信息不是错误信息，但是也要给程序员一些提示。该级别表示程序会自动调整到正常的状态，类似参数未传入，使用了默认的参数，仍符合程序员预期之内的情况。

2.2.5 ERROR

ERROR指出虽然发生错误事件，但仍然不影响系统的继续运行。打印错误和异常信息，如果不想输出太多的日志，可以使用这个级别。一般在WARN之后的级别在打印错误时，应该同时打印错误码。

2.2.6 FATAL

FATAL指出每个严重的错误事件将会导致应用程序的退出，这个级别比较高，重大错误，程序无法恢复，必须通过重启程序来解决。

2.3 日志级别大小关系

日志级别就像开关一样，来决定哪些日志方法被调用，哪些不被调用。在log4j中，日志级别的关系如下所示：

ALL<TRACE<DEBUG<INFO<WARN<ERROR<FATAL<OFF

设置了对应的级别之后，日志框架就只调用大于等于这个级别的方法。Log4j建议只使用如下的四个界别

DEBUG<INFO<WARN<ERROR

3 日志规范示例

模仿，抄写是比较好的学习方式，借鉴前人撰写日志的良好风格以形成自己的风格是不错的方式。下面是一些不错的日志记录。

3.1 TRACE日志记录示例

DRV_LOG_TRACE("Connect Execute start");
DRV_LOG_TRACE("Connect Execute finish");
DRV_LOG_TRACE("DisConnect func");
DRV_LOG_TRACE("Execute DisConnect function succeed.");
DRV_LOG_TRACE("Enter UploadEvent Func");
DRV_LOG_TRACE("extInfo = %s", Extension);
DRV_LOG_TRACE("Send a Msg ");
DRV_LOG_TRACE("- Connect Execute start");
DRV_LOG_TRACE("- Connect Execute finish");
DRV_LOG_TRACE("- Enter GetAlarmEventPro func");
DRV_LOG_TRACE("- Receive an info");
DRV_LOG_TRACE("- End Get AlarmEventPro Func");
DRV_LOG_TRACE("- DisConnect func");
DRV_LOG_TRACE("- Execute DisConnect function succeed.");
DRV_LOG_TRACE("- Enter UploadEvent Func");
DRV_LOG_TRACE("- Leave UploadEvent Func");
DRV_LOG_TRACE("- ============电网报警触发");
DRV_LOG_TRACE("- ============开始发送电流电压值");
DRV_LOG_TRACE("- ============间隔超过分钟再次发送电流电压值");

3.2 INFO日志记录示例

DRV_LOG_INFO("- UpdataEvent  nchal= %d,EventID = %d.",iChannelNo,nEventType);
DRV_LOG_INFO("- do not support doControl");
DRV_LOG_INFO("- channelId = %s, nStatusType = %d", channelId.c_str(), nStatusType);

3.3 DEBUG日志记录示例

DRV_LOG_DEBUG("- 输出报警情况:电网编号:%d,报警数量:%d,报警内容:%s.",datas.data1.chn,datas.data1.alarm_num,datas.data1.alarms);
DRV_LOG_DEBUG("- 输出报警情况:电网编号:%d,报警数量:%d,报警内容:%s.",datas.data2.chn,datas.data2.alarm_num,datas.data2.alarms);
DRV_LOG_DEBUG("- 输出报警情况:电网编号:%d,报警数量:%d,报警内容:%s.",datas.data3.chn,datas.data3.alarm_num,datas.data3.alarms);
DRV_LOG_DEBUG("- 输出报警情况:电网编号:%d,报警数量:%d,报警内容:%s.",datas.data4.chn,datas.data4.alarm_num,datas.data4.alarms);
DRV_LOG_DEBUG("- ============datas.data1.huab = %d",datas.data1.huab);
DRV_LOG_DEBUG("- ============datas.data1.hiab = %d",datas.data1.hiab);
DRV_LOG_DEBUG("- ============datas.data2.huab = %d",datas.data2.huab);
DRV_LOG_DEBUG("- ============datas.data2.hiab = %d",datas.data2.hiab);
DRV_LOG_DEBUG("- ============datas.data3.huab = %d",datas.data3.huab);
DRV_LOG_DEBUG("- ============datas.data3.hiab = %d",datas.data3.hiab);
DRV_LOG_DEBUG("- ============datas.data4.huab = %d",datas.data4.huab);
DRV_LOG_DEBUG("- ============datas.data4.hiab = %d",datas.data4.hiab);
DRV_LOG_DEBUG("- Alarm is : %s",szEvent.c_str());
DRV_LOG_DEBUG("- GetChannelExtInfo channelId=%s", channelId.c_str());
DRV_LOG_DEBUG("- nChan = %d, szInfo = %s", nChan, szInfo);

3.4 WARN日志记录示例

DRV_LOG_WARN("[0x%08x] - invaild event msg,discard it", DRV_INVALID_ARG);
DRV_LOG_WARN("[0x%08x] - Can't find channel by channelId");
DRV_LOG_WARN("[0x%08x] - [DWSdk.errorcode=0x%08x]Connect device failed", DRV_CONNECT_FAILED, sdkErrCode);
DRV_LOG_WARN("[0x%08x] - [DWSdk.errorcode=0x%08x]dw_start_receive failed", DRV_ERROR, sdkErrCode);
DRV_LOG_WARN("[0x%08x] - [DWSdk.errorcode=0x%08x]Communicate failed, socket recv error", DRV_ERROR, DW_SOCKET_RECV_ERROR);
DRV_LOG_WARN("[0x%08x] - [DWSdk.errorcode=0x%08x>other error", DRV_ERROR, iGetResult);
DRV_LOG_WARN("[0x%08x] - [DWSdk.errorcode=0x%08x>other error", DRV_ERROR, iGetResult);
DRV_LOG_WARN("[0x%08x] - SetEventCallBack should be called first", DRV_ERROR);

3.5 ERROR日志记录示例

DRV_LOG_ERROR("Init DwSDK filded;<errCode=%d>", initRet); 
DRV_LOG_ERROR("Connect device failed");
DRV_LOG_ERROR("Create thread failed");
DRV_LOG_ERROR("dw_start_receive failed");
DRV_LOG_ERROR("Communicate failed, socket recv error");
DRV_LOG_ERROR("other error<errCode=%d>", iGetResult);
DRV_LOG_ERROR("SetEventCallBack should be called first");

DRV_LOG_ERROR("[0x%08x] - [DWSdk.errorcode=0x%08x]Init DwSDK filded", DRV_INIT_FAILED, initRet);
DRV_LOG_ERROR("- [HPR.errorcode=0x%08x]Create thread failed", HPR_GetLastError());

上述代码中[0x%08x]有下述作用：

该语句出现于格式化输出时的格式字符串中。形式为

"0x%08x"

其中，0x为普通字符，输出的时候会原样输出为0x。

%08x为整型以16进制方式输出的格式字符串，会把后续对应参数的整型数字，以16进制输出。08的含义为，输出的16进制值占8位，不足部分左侧补0。

于是，如果执行

printf("0x%08x", 0x1234);

会输出0x00001234。