泽民博客 ☰ Menu

多线程安全无锁日志系统

https://github.com/yedf/handy/tree/master/handy
服务器编程中，一个优秀的日志系统需要满足几个条件



高效，日志系统不应占用太多资源
简洁，引入一个类似log4cpp这么庞大的库，不是一个令人愉快的做法
线程安全，服务器中各个线程都能同时写出日志
轮替，服务器不出故障是不重启的，半年一年的日志放到一个文件会导致文件过大
及时保存，程序故障导致异常退出，此时需要通过日志诊断问题，不缓冲的日志系统更易用



著名的日志库有log4xxx系列，提供了非常灵活的功能，当然随之而来的代价就是庞大的库。在大多数服务器应用中，所需的功能不多，我偏向于选择一个支持按时间轮替的简洁的日志库。



在前面列出的各项特点中，线程安全与轮替是个难点。引入锁则带来复杂性以及性能问题，能否设计出简洁优雅的解决方案呢？未引入轮替机制时，日志的输出可以按下面步骤实现：



使用O_APPEND方式打开文件，这个标记让write写出的内容添加到文件末尾，移动文件指针与输出内容是原子的，由操作系统来保证原子性。因此这个标记保证在多线程/多进程调用write也能够保持输出的内容不会相互覆盖错乱，nginx的日志也利用了这个标记来达到多进程不干扰
每一次log，都会生成包括了时间的最终输出字符串，调用write，写出到日志系统的文件描述符fd。当write返回时，日志已经写到操作系统，不管程序是否崩溃，只要操作系统不崩溃，那么输出的内容就会保存到日志文件中。



轮替的过程中，需要关闭当前文件并打开新文件，让新的内容写到新文件中，在多线程环境下就需要锁来同步所有线程的日志输出操作，避免写入到不合法的文件描述符中。

这里我们介绍一个不需要使用锁的新技巧，使用posix里的dup2来做到无锁轮替文件。下面是完整的步骤与描述。



//轮替时，首先重命名已打开的日志文件，保持打开状态，
rename(filename, newname);
//然后创建新的日志文件
fd = open(filename,…);
//使用dup2系统函数把fd（新）复制到fd_（旧）上
dup2(fd, fd_);
//关闭fd（新）
close(fd);
其中dup2是原子操作，它会关闭fd_并且把fd_也指向fd打开的文件。因此fd_这个文件描述符总是保持打开状态，并且值不变，但是前后指向了不同的文件，完全不会影响其他线程调用write(fd_, …)等操作。另一边write也是个原子操作，它与dup2不会交叉进行，因此保证了日志系统的正确性。



详情参见开源库handy中的logging.h和http://logging.cc，里面一部分代码采用了C++11的语法



https://github.com/yedf/handy/tree/master/handy



handy的日志系统中，日志要做的内容就是使用snprintf格式化要输出的内容，然后调用write，没有多余的工作，因此做到了简洁高效



PS：对于printf风格的日志系统，编译器的格式检查有非常大的帮助，能够在编译器检查出格式错误，而不是运行时出错然后去调试。这里有个通用的跨平台的技巧，就是先把内容用snprintf打印到一个长度为0的buffer中，例如snprintf(0, 0, VA_ARGS);这样，一旦格式字符串与后面的参数不匹配，编译器能够立刻检查出，并提示。



golang日志库
golang标准库的日志框架非常简单，仅仅提供了print，panic和fatal三个函数对于更精细的日志级别、日志文件分割以及日志分发等方面并没有提供支持。所以催生了很多第三方的日志库，但是在golang的世界里，没有一个日志库像slf4j那样在Java中具有绝对统治地位。golang中，流行的日志框架包括logrus、zap、zerolog、seelog等。
logrus是目前Github上star数量最多的日志库，目前(2018.08，下同)star数量为8119，fork数为1031。logrus功能强大，性能高效，而且具有高度灵活性，提供了自定义插件的功能。很多开源项目，如docker，prometheus等，都是用了logrus来记录其日志。
zap是Uber推出的一个快速、结构化的分级日志库。具有强大的ad-hoc分析功能，并且具有灵活的仪表盘。zap目前在GitHub上的star数量约为4.3k。
seelog提供了灵活的异步调度、格式化和过滤功能。目前在GitHub上也有约1.1k。



logrus特性
logrus具有以下特性：



完全兼容golang标准库日志模块：logrus拥有六种日志级别：debug、info、warn、error、fatal和panic，这是golang标准库日志模块的API的超集。如果您的项目使用标准库日志模块，完全可以以最低的代价迁移到logrus上。
可扩展的Hook机制：允许使用者通过hook的方式将日志分发到任意地方，如本地文件系统、标准输出、logstash、elasticsearch或者mq等，或者通过hook定义日志内容和格式等。
可选的日志输出格式：logrus内置了两种日志格式，JSONFormatter和TextFormatter，如果这两个格式不满足需求，可以自己动手实现接口Formatter，来定义自己的日志格式。
Field机制：logrus鼓励通过Field机制进行精细化的、结构化的日志记录，而不是通过冗长的消息来记录日志。
logrus是一个可插拔的、结构化的日志框架。
logrus的使用
第一个示例
最简单的使用logrus的示例如下：



package main



import (
log “github.com/sirupsen/logrus”
)



func main() {
log.WithFields(log.Fields{
“animal”: “walrus”,
}).Info(“A walrus appears”)
}



上面代码执行后，标准输出上输出如下：



time=”2018-08-11T15:42:22+08:00” level=info msg=”A walrus appears” animal=walrus
1
logrus与golang标准库日志模块完全兼容，因此您可以使用log“github.com/sirupsen/logrus”替换所有日志导入。
logrus可以通过简单的配置，来定义输出、格式或者日志级别等。



package main



import (
“os”
log “github.com/sirupsen/logrus”
)



func init() {
// 设置日志格式为json格式
log.SetFormatter(&log.JSONFormatter{})



// 设置将日志输出到标准输出（默认的输出为stderr，标准错误）

// 日志消息输出可以是任意的io.writer类型

log.SetOutput(os.Stdout)



// 设置日志级别为warn以上

log.SetLevel(log.WarnLevel) }


func main() {
log.WithFields(log.Fields{
“animal”: “walrus”,
“size”: 10,
}).Info(“A group of walrus emerges from the ocean”)



log.WithFields(log.Fields{

	"omg":    true,

	"number": 122,

}).Warn("The group's number increased tremendously!")



log.WithFields(log.Fields{

	"omg":    true,

	"number": 100,

}).Fatal("The ice breaks!") } Logger logger是一种相对高级的用法, 对于一个大型项目, 往往需要一个全局的logrus实例，即logger对象来记录项目所有的日志。如：


package main



import (
“github.com/sirupsen/logrus”
“os”
)



// logrus提供了New()函数来创建一个logrus的实例。
// 项目中，可以创建任意数量的logrus实例。
var log = logrus.New()



func main() {
// 为当前logrus实例设置消息的输出，同样地，
// 可以设置logrus实例的输出到任意io.writer
log.Out = os.Stdout



// 为当前logrus实例设置消息输出格式为json格式。

// 同样地，也可以单独为某个logrus实例设置日志级别和hook，这里不详细叙述。

log.Formatter = &logrus.JSONFormatter{}



log.WithFields(logrus.Fields{

	"animal": "walrus",

	"size":   10,

}).Info("A group of walrus emerges from the ocean") }


Fields
前一章提到过，logrus不推荐使用冗长的消息来记录运行信息，它推荐使用Fields来进行精细化的、结构化的信息记录。
例如下面的记录日志的方式：



log.Fatalf(“Failed to send event %s to topic %s with key %d”, event, topic, key)
1
在logrus中不太提倡，logrus鼓励使用以下方式替代之：



log.WithFields(log.Fields{
“event”: event,
“topic”: topic,
“key”: key,
}).Fatal(“Failed to send event”)



前面的WithFields API可以规范使用者按照其提倡的方式记录日志。但是WithFields依然是可选的，因为某些场景下，使用者确实只需要记录仪一条简单的消息。



通常，在一个应用中、或者应用的一部分中，都有一些固定的Field。比如在处理用户http请求时，上下文中，所有的日志都会有request_id和user_ip。为了避免每次记录日志都要使用log.WithFields(log.Fields{“request_id”: request_id, “user_ip”: user_ip})，我们可以创建一个logrus.Entry实例，为这个实例设置默认Fields，在上下文中使用这个logrus.Entry实例记录日志即可。



requestLogger := log.WithFields(log.Fields{“request_id”: request_id, “user_ip”: user_ip})
requestLogger.Info(“something happened on that request”) # will log request_id and user_ip
requestLogger.Warn(“something not great happened”)



Hook
logrus最令人心动的功能就是其可扩展的HOOK机制了，通过在初始化时为logrus添加hook，logrus可以实现各种扩展功能。



Hook接口
logrus的hook接口定义如下，其原理是每此写入日志时拦截，修改logrus.Entry。



// logrus在记录Levels()返回的日志级别的消息时会触发HOOK，
// 按照Fire方法定义的内容修改logrus.Entry。
type Hook interface {
Levels() []Level
Fire(*Entry) error
}



一个简单自定义hook如下，DefaultFieldHook定义会在所有级别的日志消息中加入默认字段appName=”myAppName”。



type DefaultFieldHook struct {
}



func (hook *DefaultFieldHook) Fire(entry *log.Entry) error {
entry.Data[“appName”] = “MyAppName”
return nil
}



func (hook *DefaultFieldHook) Levels() []log.Level {
return log.AllLevels
}



hook的使用也很简单，在初始化前调用log.AddHook(hook)添加相应的hook即可。



logrus官方仅仅内置了syslog的hook。
此外，但Github也有很多第三方的hook可供使用，文末将提供一些第三方HOOK的连接。



记录文件名和行号
logrus的一个很致命的问题就是没有提供文件名和行号，这在大型项目中通过日志定位问题时有诸多不便。Github上的logrus的issue#63：Log filename and line number创建于2014年，四年过去了仍是open状态~~~
网上给出的解决方案分位两类，一就是自己实现一个hook；二就是通过装饰器包装logrus.Entry。两种方案网上都有很多代码，但是大多无法正常工作。但总体来说，解决问题的思路都是对的：通过标准库的runtime模块获取运行时信息，并从中提取文件名，行号和调用函数名。



标准库runtime模块的Caller(skip int)函数可以返回当前goroutine调用栈中的文件名，行号，函数信息等，参数skip表示表示返回的栈帧的层次，0表示runtime.Caller的调用着。返回值包括响应栈帧层次的pc(程序计数器)，文件名和行号信息。为了提高效率，我们先通过跟踪调用栈发现，从runtime.Caller()的调用者开始，到记录日志的生成代码之间，大概有8到11层左右，所有我们在hook中循环第8到11层调用栈应该可以找到日志记录的生产代码。



此外，runtime.FuncForPC(pc uintptr) *Func可以返回指定pc的函数信息。
所有我们要实现的hook也是基于以上原理，使用runtime.Caller()依次循环调用栈的第7~11层，过滤掉sirupsen包内容，那么第一个非siupsenr包就认为是我们的生产代码了，并返回pc以便通过runtime.FuncForPC()获取函数名称。然后将文件名、行号和函数名组装为source字段塞到logrus.Entry中即可。



import (
“fmt”
log “github.com/sirupsen/logrus”
“runtime”
“strings”
)



// line number hook for log the call context,
type lineHook struct {
Field string
// skip为遍历调用栈开始的索引位置
Skip int
levels []log.Level
}



// Levels implement levels
func (hook lineHook) Levels() []log.Level {
return log.AllLevels
}



// Fire implement fire
func (hook lineHook) Fire(entry *log.Entry) error {
entry.Data[hook.Field] = findCaller(hook.Skip)
return nil
}



func findCaller(skip int) string {
file := “”
line := 0
var pc uintptr
// 遍历调用栈的最大索引为第11层.
for i := 0; i < 11; i++ {
file, line, pc = getCaller(skip + i)
// 过滤掉所有logrus包，即可得到生成代码信息
if !strings.HasPrefix(file, “logrus”) {
break
}
}



fullFnName := runtime.FuncForPC(pc)



fnName := ""

if fullFnName != nil {

	fnNameStr := fullFnName.Name()

    // 取得函数名

	parts := strings.Split(fnNameStr, ".")

	fnName = parts[len(parts)-1]

}



return fmt.Sprintf("%s:%d:%s()", file, line, fnName) }


func getCaller(skip int) (string, int, uintptr) {
pc, file, line, ok := runtime.Caller(skip)
if !ok {
return “”, 0, pc
}
n := 0



// 获取包名

for i := len(file) - 1; i > 0; i-- {

	if file[i] == '/' {

		n++

		if n >= 2 {

			file = file[i+1:]

			break

		}

	}

}

return file, line, pc } 效果如下：


time=”2018-08-11T19:10:15+08:00” level=warning msg=”postgres_exporter is ready for scraping on 0.0.0.0:9295…” source=”postgres_exporter/main.go:60:main()”
time=”2018-08-11T19:10:17+08:00” level=error msg=”!!!msb info not found” source=”postgres/postgres_query.go:63:QueryPostgresInfo()”
time=”2018-08-11T19:10:17+08:00” level=error msg=”get postgres instances info failed, scrape metrics failed, error:msb env not found” source=”collector/exporter.go:71:Scrape()”



日志本地文件分割
logrus本身不带日志本地文件分割功能，但是我们可以通过file-rotatelogs进行日志本地文件分割。 每次当我们写入日志的时候，logrus都会调用file-rotatelogs来判断日志是否要进行切分。关于本地日志文件分割的例子网上很多，这里不再详细介绍，奉上代码：



import (
“github.com/lestrrat-go/file-rotatelogs”
“github.com/rifflock/lfshook”
log “github.com/sirupsen/logrus”
“time”
)



func newLfsHook(logLevel *string, maxRemainCnt uint) log.Hook {
writer, err := rotatelogs.New(
logName+”.%Y%m%d%H”,
// WithLinkName为最新的日志建立软连接，以方便随着找到当前日志文件
rotatelogs.WithLinkName(logName),



    // WithRotationTime设置日志分割的时间，这里设置为一小时分割一次

    rotatelogs.WithRotationTime(time.Hour),

    

    // WithMaxAge和WithRotationCount二者只能设置一个，

    // WithMaxAge设置文件清理前的最长保存时间，

    // WithRotationCount设置文件清理前最多保存的个数。

	//rotatelogs.WithMaxAge(time.Hour*24),

	rotatelogs.WithRotationCount(maxRemainCnt),

)



if err != nil {

	log.Errorf("config local file system for logger error: %v", err)

}



level, ok := logLevels[*logLevel]



if ok {

	log.SetLevel(level)

} else {

	log.SetLevel(log.WarnLevel)

}



lfsHook := lfshook.NewHook(lfshook.WriterMap{

	log.DebugLevel: writer,

	log.InfoLevel:  writer,

	log.WarnLevel:  writer,

	log.ErrorLevel: writer,

	log.FatalLevel: writer,

	log.PanicLevel: writer,

}, &log.TextFormatter{DisableColors: true})



return lfsHook }


使用上述本地日志文件切割的效果如下：



将日志发送到elasticsearch
将日志发送到elasticsearch是很多日志监控系统的选择，将logrus日志发送到elasticsearch的原理是在hook的每次fire调用时，使用golang的es客户端将日志信息写到elasticsearch。elasticsearch官方没有提供golang客户端，但是有很多第三方的go语言客户端可供使用，我们选择elastic。elastic提供了丰富的文档，以及Java中的流式接口，使用起来非常方便。



client, err := elastic.NewClient(elastic.SetURL(“http://localhost:9200”))
if err != nil {
log.Panic(err)
}



// Index a tweet (using JSON serialization)
tweet1 := Tweet{User: “olivere”, Message: “Take Five”, Retweets: 0}
put1, err := client.Index().
Index(“twitter”).
Type(“tweet”).
Id(“1”).
BodyJson(tweet1).
Do(context.Background())



考虑到logrus的Fields机制，可以实现如下数据格式：



msg := struct {
Host string
Timestamp string json:"@timestamp"
Message string
Data logrus.Fields
Level string
}



其中Host记录产生日志主机信息，在创建hook是指定。其他数据需要从logrus.Entry中取得。测试过程我们选择按照此原理实现的第三方HOOK：elogrus。其使用如下：



import (
“github.com/olivere/elastic”
“gopkg.in/sohlich/elogrus”
)



func initLog() {
client, err := elastic.NewClient(elastic.SetURL(“http://localhost:9200”))
if err != nil {
log.Panic(err)
}
hook, err := elogrus.NewElasticHook(client, “localhost”, log.DebugLevel, “mylog”)
if err != nil {
log.Panic(err)
}
log.AddHook(hook)
}



从Elasticsearch查询得到日志存储，效果如下：



GET http://localhost:9200/mylog/_search



HTTP/1.1 200 OK
content-type: application/json; charset=UTF-8
transfer-encoding: chunked



{
“took”: 1,
“timed_out”: false,
“shards”: {
“total”: 5,
“successful”: 5,
“failed”: 0
},
“hits”: {
“total”: 2474,
“max_score”: 1.0,
“hits”: [
{
“_index”: “mylog”,
“_type”: “log”,
“_id”: “AWUw13jWnMZReb-jHQup”,
“_score”: 1.0,
“_source”: {
“Host”: “localhost”,
“@timestamp”: “2018-08-13T01:12:32.212818666Z”,
“Message”: “!!!msb info not found”,
“Data”: {},
“Level”: “ERROR”
}
},
{
“_index”: “mylog”,
“_type”: “log”,
“_id”: “AWUw13jgnMZReb-jHQuq”,
“_score”: 1.0,
“_source”: {
“Host”: “localhost”,
“@timestamp”: “2018-08-13T01:12:32.223103348Z”,
“Message”: “get postgres instances info failed, scrape metrics failed, error:msb env not found”,
“Data”: {
“source”: “collector/exporter.go:71:Scrape()”
},
“Level”: “ERROR”
}
},
//…
{
“_index”: “mylog”,
“_type”: “log”,
“_id”: “AWUw2f1enMZReb-jHQu”,
“_score”: 1.0,
“_source”: {
“Host”: “localhost”,
“@timestamp”: “2018-08-13T01:15:17.212546892Z”,
“Message”: “!!!msb info not found”,
“Data”: {
“source”: “collector/exporter.go:71:Scrape()”
},
“Level”: “ERROR”
}
},
{
“_index”: “mylog”,
“_type”: “log”,
“_id”: “AWUw2NhmnMZReb-jHQu1”,
“_score”: 1.0,
“_source”: {
“Host”: “localhost”,
“@timestamp”: “2018-08-13T01:14:02.21276903Z”,
“Message”: “!!!msb info not found”,
“Data”: {},
“Level”: “ERROR”
}
}
]
}
}



Response code: 200 (OK); Time: 16ms; Content length: 3039 bytes



将日志发送到其他位置
将日志发送到日志中心也是logrus所提倡的，虽然没有提供官方支持，但是目前Github上有很多第三方hook可供使用：



logrus_amqp：Logrus hook for Activemq。
logrus-logstash-hook:Logstash hook for logrus。
mgorus:Mongodb Hooks for Logrus。
logrus_influxdb:InfluxDB Hook for Logrus。
logrus-redis-hook:Hook for Logrus which enables logging to RELK stack (Redis, Elasticsearch, Logstash and Kibana)。
等等，上述第三方hook我这里没有具体验证，大家可以根据需要自行尝试。



其他注意事项
Fatal处理
和很多日志框架一样，logrus的Fatal系列函数会执行os.Exit(1)。但是logrus提供可以注册一个或多个fatal handler函数的接口logrus.RegisterExitHandler(handler func() {} )，让logrus在执行os.Exit(1)之前进行相应的处理。fatal handler可以在系统异常时调用一些资源释放api等，让应用正确的关闭。



线程安全
默认情况下，logrus的api都是线程安全的，其内部通过互斥锁来保护并发写。互斥锁工作于调用hooks或者写日志的时候，如果不需要锁，可以调用logger.SetNoLock()来关闭之。可以关闭logrus互斥锁的情形包括：



没有设置hook，或者所有的hook都是线程安全的实现。
写日志到logger.Out已经是线程安全的了，如logger.Out已经被锁保护，或者写文件时，文件是以O_APPEND方式打开的，并且每次写操作都小于4k。



前一篇文章我们看到了Golang标准库中log模块的使用，那么它是如何实现的呢？下面我从log.Logger开始逐步分析其实现。 其源码可以参考官方地址



1.Logger结构
首先来看下类型Logger的定义：



1
2
3
4
5
6
7
type Logger struct {
mu sync.Mutex // ensures atomic writes; protects the following fields
prefix string // prefix to write at beginning of each line
flag int // properties
out io.Writer // destination for output
buf []byte // for accumulating text to write
}
主要有5个成员，其中3个我们比较熟悉，分别是表示Log前缀的 “prefix”，表示Log头标签的 “flag” ，以及Log的输出目的地out。 buf是一个字节数组，主要用来存放即将刷入out的内容，相当于一个临时缓存，在对输出内容进行序列化时作为存储目的地。 mu是一个mutex主要用来作线程安全的实习，当有多个goroutine同时往一个目的刷内容的时候，通过mutex保证每次写入是一条完整的信息。



2.std及整体结构
在前一篇文章中我们提到了log模块提供了一套包级别的简单接口，使用该接口可以直接将日志内容打印到标准错误。那么该过程是怎么实现的呢？其实就是通过一个内置的Logger类型的变量 “std” 来实现的。该变量使用：



1
var std = New(os.Stderr, “”, LstdFlags)
进行初始化，默认输出到系统的标准输出 “os.Stderr” ,前缀为空，使用日期加时间作为Log抬头。



当我们调用 log.Print的时候是怎么执行的呢？我们看其代码：



1
2
3
func Print(v …interface{}) {
std.Output(2, fmt.Sprint(v…))
}
这里实际就是调用了Logger对象的 Output方法，将日志内容按照fmt包中约定的格式转义后传给Output。Output定义如下 :



1
func (l *Logger) Output(calldepth int, s string) error



其中s为日志没有加前缀和Log抬头的具体内容，xxxxx 。该函数执行具体的将日志刷入到对应的位置。



3.核心函数的实现
Logger.Output是执行具体的将日志刷入到对应位置的方法。



该方法首先根据需要获得当前时间和调用该方法的文件及行号信息。然后调用formatHeader方法将Log的前缀和Log抬头先格式化好 放入Logger.buf中，然后再将Log的内容存入到Logger.buf中，最后调用Logger.out.Write方法将完整的日志写入到输出目的地中。



由于写入文件以及拼接buf的过程是线程非安全的，因此使用mutex保证每次写入的原子性。



1
2
l.mu.Lock()
defer l.mu.Unlock()
将buf的拼接和文件的写入放入这个后面，使得在多个goroutine使用同一个Logger对象是，不会弄乱buf，也不会杂糅的写入。



该方法的第一个参数最终会传递给runtime.Caller的skip，指的是跳过的栈的深度。这里我记住给2就可以了。这样就会得到我们调用log 是所处的位置。



在golang的注释中说锁住 runtime.Caller的过程比较重，这点我还是不很了解，只是从代码中看到其在这里把锁打开了。



1
2
3
4
5
6
7
8
9
10
11
if l.flag&(Lshortfile|Llongfile) != 0 {
// release lock while getting caller info - it’s expensive.
l.mu.Unlock()
var ok bool
_, file, line, ok = runtime.Caller(calldepth)
if !ok {
file = “???”
line = 0
}
l.mu.Lock()
}
在formatHeader里面首先将前缀直接复制到Logger.buf中,然后根据flag选择Log抬头的内容，这里用到了一个log模块实现的 itoa的方法，作用类似c的itoa,将一个整数转换成一个字符串。只是其转换后将结果直接追加到了buf的尾部。



纵观整个实现，最值得学习的就是线程安全的部分。在什么位置合适做怎样的同步操作。



4.对外接口的实现
在了解了核心格式化和输出结构后，在看其封装就非常简单了，几乎都是首先用Output进行日志的记录，然后在必要的时候 做os.exit或者panic的操作，这里看下Fatal的实现。



1
2
3
4
5
6
7
8
9
10
11
12
13
14
func (l *Logger) Fatal(v …interface{}) {
l.Output(2, fmt.Sprint(v…))
os.Exit(1)
}
// Fatalf is equivalent to l.Printf() followed by a call to os.Exit(1).
func (l *Logger) Fatalf(format string, v …interface{}) {
l.Output(2, fmt.Sprintf(format, v…))
os.Exit(1)
}
// Fatalln is equivalent to l.Println() followed by a call to os.Exit(1).
func (l *Logger) Fatalln(v …interface{}) {
l.Output(2, fmt.Sprintln(v…))
os.Exit(1)
}
这里也验证了我们之前做的Panic的结果，先做输出日志操作。再进行panic。



5.Golang的log模块设计
Golang的log模块主要提供了三类接口 ：



Print ： 一般的消息输出



Fatal : 类似assert一般的强行退出



Panic ： 相当于OO里面常用的异常捕获



与其说log模块提供了三类日志接口，不如说log模块仅仅是对类C中的 printf、assert、try…catch…的简单封装。Golang的log模块 并没有对log进行分类、分级、过滤等其他类似log4j、log4c、zlog当中常见的概念。当然在使用中你可以通过添加prefix,来进行简单的 分级，或者改变Logger.out改变其输出位置。但这些并没有在API层面给出直观的接口。



Golang的log模块就像是其目前仅专注于为服务器编程一样，他的log模块也专注于服务器尤其是基础组件而服务。就像nginx、redis、lighttpd、keepalived自己为自己写了一个简单的日志模块而没有实现log4c那样庞大且复杂的日志模块一样。他的日志模块仅仅需要为 本服务按照需要的格式和方式提供接口将日志输出到目的地即可。



Golang的log模块可以进行一般的信息记录，assert时的信息输出，以及出现异常时的日志记录，通过对其Print的包装可以实现更复杂的 输出。因此这个log模块可谓是语言层面上非常基础的一层库，反应的是语言本身的特征而不是一个服务应该怎样怎样。



为什么要用zap来写日志
原来是写PHP的，一直用的error_log，第一次写Go项目的时候，还真不知道该怎么写日志，后来就按照PHP的写法自己不成规范的捣鼓写。去了新公司之后，发现用的是zap。后来查询 了解了下zap，前同事反应他们很多大公司都在使用zap写日志，GitHub上star 高达7K多，足以说明它受欢迎的程度。



1.zap是Uber开源的日志库；
2.很多大的公司和小的公司都在使用；
3.跟seelog、logrus等类库相比，高性能是它最突出的优势；
我想以上几个原因就已经说明了它的广泛性、稳定性，就值得我们去尝试。



怎么使用zap
我们说下简单的使用案例
首相当然是下载
go get -u go.uber.org/zap
先贴一个我这边常用的zap的配置



zap.Config{
Level: zap.NewAtomicLevelAt(zap.DebugLevel),
Development: true,
Encoding: “json”,
EncoderConfig: zapcore.EncoderConfig{
TimeKey: “t”,
LevelKey: “level”,
NameKey: “log”,
CallerKey: “caller”,
MessageKey: “msg”,
StacktraceKey: “trace”,
LineEnding: zapcore.DefaultLineEnding,
EncodeLevel: zapcore.LowercaseLevelEncoder,
EncodeTime: 时间格式函数,
EncodeDuration: zapcore.SecondsDurationEncoder,
EncodeCaller: zapcore.ShortCallerEncoder,
},
OutputPaths: []string{“/tmp/zap.log”},
ErrorOutputPaths: []string{“/tmp/zap.log”},
InitialFields: map[string]interface{}{
“app”: “test”,
},
}
基本配置的说明
Level：日志级别，跟其他语言是一样的。只不过它需要的类型是AtomicLevel。所以需要使用zap.NewAtomicLevelAt做下如下的转化。



zap.NewAtomicLevelAt(zap.DebugLevel)
zap.DebugLevel
zap.InfoLevel
zap.WarnLevel
zap.ErrorLevel
Development：bool 是否是开发环境。如果是开发模式，对DPanicLevel进行堆栈跟踪
DisableCaller：bool 禁止使用调用函数的文件名和行号来注释日志。默认进行注释日志
DisableStacktrace：bool 是否禁用堆栈跟踪捕获。默认对Warn级别以上和生产error级别以上的进行堆栈跟踪。
Encoding：编码类型，目前两种json 和 console【按照空格隔开】,常用json
EncoderConfig：生成格式的一些配置–TODO 后面我们详细看下EncoderConfig配置各个说明
OutputPaths：[]string 日志写入文件的地址
ErrorOutputPaths：[]string 将系统内的error记录到文件的地址
InitialFields：map[string]interface{} 加入一些初始的字段数据，比如项目名
当然了，如果想控制台输出，OutputPaths和ErrorOutputPaths不能配置为文件地址，而应该改为stdout。



关于config的配置，具体的可以参考文件里面的注释
go.uber.org/zap/config.go
type Config struct



EncoderConfig配置说明
MessageKey：输入信息的key名
LevelKey：输出日志级别的key名
TimeKey：输出时间的key名
NameKey CallerKey StacktraceKey跟以上类似，看名字就知道
LineEnding：每行的分隔符。基本zapcore.DefaultLineEnding 即”\n”
EncodeLevel：基本zapcore.LowercaseLevelEncoder。将日志级别字符串转化为小写
EncodeTime：输出的时间格式
EncodeDuration：一般zapcore.SecondsDurationEncoder,执行消耗的时间转化成浮点型的秒
EncodeCaller：一般zapcore.ShortCallerEncoder，以包/文件:行号 格式化调用堆栈
EncodeName：可选值。



具体EncoderConfig的说明，可以参考文件里面的注释
go.uber.org/zapcore/encoder.go
type EncoderConfig struct



举个栗子
你扯这么多配置说明，谁有时间看这玩意，写个常用的让大家照着用就好了嘛。



package main



import (
“fmt”
“go.uber.org/zap”
“go.uber.org/zap/zapcore”
“time”
)



var logger *zap.Logger
func formatEncodeTime(t time.Time, enc zapcore.PrimitiveArrayEncoder) {
enc.AppendString(fmt.Sprintf(“%d%02d%02d_%02d%02d%02d”, t.Year(), t.Month(), t.Day(), t.Hour(), t.Minute(), t.Second()))
}



func FormateLog(args []interface{}) *zap.Logger {
log := logger.With(ToJsonData(args))
return log
}



func Debug(msg string, args …interface{}) {
FormateLog(args).Sugar().Debugf(msg)
}



func ToJsonData(args []interface{}) zap.Field {
det := make([]string, 0)
if len(args) > 0 {
for _, v := range args {
det = append(det, fmt.Sprintf(“%+v”, v))
}
}
zap := zap.Any(“detail”, det)
return zap
}



func InitZapLog() {
cfg := zap.Config{
Level: zap.NewAtomicLevelAt(zap.DebugLevel),
Development: true,
Encoding: “json”,
EncoderConfig: zapcore.EncoderConfig{
TimeKey: “t”,
LevelKey: “level”,
NameKey: “logger”,
CallerKey: “caller”,
MessageKey: “msg”,
StacktraceKey: “trace”,
LineEnding: zapcore.DefaultLineEnding,
EncodeLevel: zapcore.LowercaseLevelEncoder,
EncodeTime: formatEncodeTime,
EncodeDuration: zapcore.SecondsDurationEncoder,
EncodeCaller: zapcore.ShortCallerEncoder,
},
OutputPaths: []string{“/tmp/zap.log”},
ErrorOutputPaths: []string{“/tmp/zap.log”},
InitialFields: map[string]interface{}{
“app”: “test”,
},
}
var err error
logger, err = cfg.Build()
if err != nil {
panic(“log init fail:” + err.Error())
}
}



func main() {
InitZapLog()
defer logger.Sync()
a := []string{“test”,”hello”,”world”}
Debug(“output”,a)
}
执行下，就会在日志文件上输入按照我们配置日志格式。



tail -f /tmp/zap.log
{“level”:”debug”,”t”:”20190630_044053”,”caller”:”myproject/main.go:21”,”msg”:”output”,”app”:”test”,”detail”:[“[test hello world]”]}
然后我们试下控制台输出，修改三个console相关的配置代码
···
OutputPaths: []string{“stdout”},
ErrorOutputPaths: []string{“stdout”},
控制台窗口就会输出
{“level”:”debug”,”t”:”20190630_092533”,”caller”:”myproject/main.go:21”,”msg”:”output”,”app”:”test”,”detail”:[“[test hello world]”]}
···



当然了，zap最想的使用和文档，看官网嘛
https://github.com/uber-go/zap
https://godoc.org/go.uber.org/zap
glog简介
glog是著名的google开源C++日志库glog的golang版本，glog是一个轻量级的日志库，上手简单不需要配置文件并且稳定高效，但是可以自定义控制的内容就少了。 glog主要有以下几个特点：



glog有四种日志等级INFO < WARING < ERROR < FATAL，不同等级的日志是打印到不同文件的，低等级的日志文件中（INFO）会包含高等级的日志信息（ERROR）
通过命令行传递参数 –log_dir指定日志文件的存放目录，默认为os.TempDir()
可以根据文件大小切割日志文件，但是不能根据日期切割日志文件
日志输出格式是固定的(Lmmdd hh:mm:ss.uuuuuu threadid file:line] msg…)不可以自定义
在程序开始时需要调用flag.Parse()解析命令行参数，在程序退出时需要调用glog.Flush() 确保将缓存区中的内容输出到文件中。
使用事例
func main() {
//初始化命令行参数
flag.Parse()



//退出时调用，确保日志写入文件中

defer glog.Flush()



glog.Info("hello, glog")

glog.Warning("warning glog")

glog.Error("error glog")



glog.Infof("info %d", 1)

glog.Warningf("warning %d", 2)

glog.Errorf("error %d", 3)


}
//假设编译后的可执行程序名为demo,运行时指定log_dir参数将日志文件保存到特定的目录
// ./demo –log_dir=./log
源码分析
我们顺着事例代码中的 glog.Error(“error glog”) 这行代码来看下，来看下日志内容是如何输出到文件中去的。



func Error(args …interface{}) {
logging.print(errorLog, args…)
}



//errorLog是glog定义的日志等级标记，底层是一个int32类型的变量
type severity int32
const (
infoLog severity = iota
warningLog
errorLog
fatalLog
numSeverity = 4
)



// Error函数实际只是做了一层简单的封装，实际调用的是loggering对象的print函数，loggering是一个loggingT类型的全局变量



func (l *loggingT) print(s severity, args …interface{}) {
l.printDepth(s, 1, args…)
}
//printDepth可以指定输出日志栈的调用层次

func (l *loggingT) printDepth(s severity, depth int, args …interface{}) {
//header构造格式化的附加信息 Lmmdd hh:mm:ss.uuuuuu threadid file:line]，glog在这个过程中做了很多优化，具体查看源码
//header函数中会从一个freeList中取buffer对象，如果不存在则会创建新的buffer对象，在使用完后调用 putBuffer将buffer放回到freeList中
buf, file, line := l.header(s, depth)
fmt.Fprint(buf, args…)
if buf.Bytes()[buf.Len()-1] != ‘\n’ {
buf.WriteByte(‘\n’)
}
l.output(s, buf, file, line, false)
}



func (l *loggingT) output(s severity, buf *buffer, file string, line int, alsoToStderr bool) {
data := buf.Bytes()
//glog会为每个级别的日志创建不同的日志文件，打印日志时首先要保证该级别的日志文件已存在
if l.file[s] == nil {
if err := l.createFiles(s); err != nil {
os.Stderr.Write(data)
l.exit(err)
}
}
//glog会将高级别的日志信息打印到低级别的日志文件中
//去掉代码段中的 fallthrough，则可以实现error日志只输出到error文件中，而不会继续输出到info级别的日志文件中
switch s {
case fatalLog:
l.file[fatalLog].Write(data)
fallthrough
case errorLog:
l.file[errorLog].Write(data)
fallthrough
case warningLog:
l.file[warningLog].Write(data)
fallthrough
case infoLog:
l.file[infoLog].Write(data)
}
if s == fatalLog {
//如果是FATAL日志信息，则退出程序
os.Exit(255)
}
//将使用完的buffer对象放到缓冲池中
l.putBuffer(buf)
}



//loggingT.file是一个flushSyncWriter接口类型的数组，在glog中实际的对象是syncBuffer，syncBuffer封装了底层的写文件操作，增加了缓冲区避免过于频繁的系统调用提高写日志效率
type syncBuffer struct {
*bufio.Writer
file *os.File
sev severity
nbytes uint64 // The number of bytes written to this file
}
//写入日志前会判断日志文件是否已经超过指定的最大尺寸，如果超过则创建新的日志文件
//日志内容会先写入到内存中 sb.Writer = bufio.NewWriterSize(sb.file, bufferSize)
func (sb *syncBuffer) Write(p []byte) (n int, err error) {
if sb.nbytes+uint64(len(p)) >= MaxSize {
if err := sb.rotateFile(time.Now()); err != nil {
sb.logger.exit(err)
}
}
n, err = sb.Writer.Write(p)
sb.nbytes += uint64(n)
return
}



//我们通过调用syncBuffer.Write函数将日志内容输出，但是syncBuffer缓冲区中的内容是在什么时候输出到文件中的呢
//glog的init函数中会开启一个 goroutine定时的调用 flushSyncWriter的Flush函数将内存中的日志内容刷到文件中
func init() {
go logging.flushDaemon()
}



func (l *loggingT) flushDaemon() {
for _ = range time.NewTicker(flushInterval).C {
for s := fatalLog; s >= infoLog; s– {
file := l.file[s]
if file != nil {
file.Flush()
file.Sync()

}
}
}
vlog简介
一般的日志库会提供日志输出级别，当日志信息的级别低于输出级别时则不会输出该日志信息。我们使用其他日志库时会使用log.Debug()打印出调试信息，在测试环境下将日志库的输出级别设置为DEBUG，调试信息就会输出便于我们查看程序的具体运行情况，而在线上程序中将日志的输出级别设置为INFO调试信息就不会输出。 glog则采用另外一种方式实现这种功能，glog提供让用户自定义分级信息的功能，用户自定义分级与glog自带的日志等级(INFO ERROR)是完全分离的，在命令行参数设置中独立设置“v”或“vmodule”参数来控制。



if glog.V(1) {
glog.Info(“Starting transaction…”)
}
glog.V(1).Infoln(“Processed”, nItems, “elements”)
在测试环境下我们运行程序时指定用户自定义级别为1 (–v=1)，上面的日志信息就会输出。 而在线上环境中指定自定义级别为0(–v=0)，上面的日志信息则不会输出。



func init(){
flag.Var(&logging.verbosity, “v”, “log level for V logs”)
}



type Verbose bool



func V(level Level) Verbose {
if logging.verbosity.get() >= level {
return Verbose(true)
}
return Verbose(false)
}



func (v Verbose) Info(args …interface{}) {
if v {
logging.print(infoLog, args…)
}
}
修改glog源码
glog有些功能与我们常用的日志库不太一样或者没有我们期望的功能，可以修改glog的源码来实现我们的需求。比如我们之前使用的日志库是有DEBUG INFO ERROR FATAL级别的，我们可以修改glog源码增加DEBUG级别，删除WARN级别，已于我们的原有系统保持一致。 具体修改内容查看github源码



设置等级控制日志的输出 实现原理：定义一个输出等级变量，提供接口给用户可以设置该变量的值，默认为INFO，在输出日志时检查日志信息的等级是否大于输出等级，如果大于则输出日志信息否则不输出



var outputSeverity severity
//outputLevel 必须为INFO ERROR等字符串，否则panic
//SetLevelString 不是线程安全的，主要是因为我都是在程序开启时在主进程中调用一次SetLevelString函数，而不会在程序运行中随意调用



func SetLevelString(outputLevel string) {
severity, ok := severityByName(outputLevel)
if !ok {
panic(fmt.Errorf(“unknown severity name %s”, outputLevel))
}
outputSeverity = severity
}



func (l *loggingT) println(s severity, args …interface{}) {
if s < outputSeverity {
return
}
buf, file, line := l.header(s, 0)
fmt.Fprintln(buf, args…)
l.output(s, buf, file, line, false)
}
//用户在测试环境下调用 SetLevelString(“DEBUG”)则调试信息能够正常输出到文件中，而在线上环境下调用SetLevelString(“INFO”)屏蔽调试信息
每天自动切割日志文件



实现原理：在创建日志文件时记录下创建文件的日期(MMDD)，输出每条日志信息时判断当前日期与日志文件的创建日期是否一致，如果不一致则创建新的日志文件。



func init() {

    flag.BoolVar(&logging.dailyRolling, "dailyRolling", false, " weather to handle log files daily")

}


func (sb *syncBuffer) Write(p []byte) (n int, err error) {
if logging.dailyRolling {
if sb.createdDate != string(p[1:5]) {
if err := sb.rotateFile(time.Now()); err != nil {
sb.logger.exit(err)
}
}
}
//写日志信息
}



func (sb *syncBuffer) rotateFile(now time.Time) error {
sb.createdDate = fmt.Sprintf(“%02d%02d”, month, day)
//创建新的日志文件
}



https://github.com/google/glog
写在前面
Golang 的log包内容不多，说实话，直接用来做日志开发有些简易。主要是缺少一些功能：



按日志级别打印和控制日志；
日志文件自动分割；
异步打印日志。
按日志级别打印和控制日志
我们实现的日志模块将会支持4个级别：



const (
LevelError = iota
LevelWarning
LevelInformational
LevelDebug
)
定义一个日志结构体：



type Logger struct {
level int
l *log.Logger
}



func (ll *Logger) Error(format string, v …interface{}) {
if LevelError > ll.level {
return
}
msg := fmt.Sprintf(“[E] “+format, v…)
ll.l.Printf(msg)
}
这样就能实现日志级别控制输出，并且打印的时候追加一个标记，比如上面的例子，Error 级别就会追加[E]。



这个实现已经可以了，但是还是有优化的空间。比如打印追加标记[E]的时候，用的是字符串加法。字符串加法会申请新的内存，对性能不是很优化。我们需要通过字符数组来优化。



但我不会这么去优化了。这个时候看一下 log 包的 API，可以发现原生包是支持设置前缀的：



func (l *Logger) SetPrefix(prefix string)
再去看一下具体的实现：



func (l Logger) formatHeader(buf *[]byte, t time.Time, file string, line int) {
*buf = append(buf, l.prefix…)
原生包在写日志前缀的时候就用到了[]byte来提升性能。既然人家已经提供了，我们还是不要自己造了。那么问题来了，设置前缀是初始化的时候就要设置，打印的时候自动输出出来。一个log.Logger对象只能有一个前缀，而我们需要4种级别的前缀，这个如何打印？



type Logger struct {
level int
err *log.Logger
warn *log.Logger
info *log.Logger
debug *log.Logger
}
我们直接申请4个日志对象就能解决。为了保证所有级别都打印到同一个文件里面，初始化的时候设置成同一个io.Writer即可。



logger := new(LcLogger)



logger.err = log.New(w, “[E] “, flag)
logger.warn = log.New(w, “[W] “, flag)
logger.info = log.New(w, “[I] “, flag)
logger.debug = log.New(w, “[D] “, flag)
设置日志级别：



func (ll *Logger) SetLevel(l int) {
ll.level = l
}
打印的时候根据日志级别控制输出。（讲一个我遇到的坑。之前有一次打印日志打太多了，磁盘都打满了，就寻思着把日志级别调高减少打印内容。把级别调成 Error 后发现还是没有效果，最后看了看代码发现出问题的日志打印的是 Error 级别。。。Error级别的日志要尽量少打。）



func (ll *Logger) Error(format string, v …interface{}) {
if LevelError > ll.level {
return
}
ll.err.Printf(format, v…)
}
日志文件自动分割
日志文件需要自动分割。否则一个文件过大，清理磁盘的时候这个文件因为还是打印日志没办法清理。



日志分割我觉得简单的以大小分割就好。



那么日志分割功能如何接入咱们上面实现的日志模块呢？关键就在io.Writer。



type Writer interface {
Write(p []byte) (n int, err error)
}
Writer这个接口只有一个方法，如此简单。原生包默认打印日志会输出到os.Stderr里面，这是一个os.File类型的变量，它实现了Writer这个接口。



func (f *File) Write(b []byte) (n int, err error)
写日志的时候，log 包会自动调用Write方法。我们可以自己实现一个Writer，在Write的时候计算一下写入此行日志之后当前日志文件大小，如果超过设定的值，执行一次分割。按日子分割日志也是这个时候操作。



推荐用 gopkg.in/natefinch/lumberjack.v2 这个包来做日志分割，功能很强大。



jack := &lumberjack.Logger{
Filename: lfn,
MaxSize: maxsize, // megabytes
}
使用也很简单，jack对象就是一个Writer了，可以直接复制给Logger使用。



日志的异步输出
协程池也整个包：github.com/ivpusic/grpool。协程池就不展开说了，有兴趣的可以看看这个包的实现。



日志的结构体再一次升级：



type Logger struct {
level int
err *log.Logger
warn *log.Logger
info *log.Logger
debug *log.Logger
p *grpool.Pool
}
初始化：



logger.p = grpool.NewPool(numWorkers, jobQueueLen)
日志输出：



func (ll *Logger) Error(format string, v …interface{}) {
if LevelError > ll.level {
return
}
ll.p.JobQueue <- func() {
ll.err.Printf(format, v…)
}
}
日志行号
如果你一步一步按上面的做了，打印日志设置了Lshortfile，展示行号的花，你可能会发现这个时候打印出来的行号有问题。打印日志的时候用到了runtime里面的堆栈信息，因为我们封装了一层，所以打印的堆栈深度会发生变化。简单的说就是深了一层。



原生的日志包提供了func (l *Logger) Output(calldepth int, s string) error来控制日志堆栈深度输出，我们再次对代码进行调整。



type Logger struct {
level int
err *log.Logger
warn *log.Logger
info *log.Logger
debug *log.Logger
p *grpool.Pool
depth int
}



func (ll *Logger) Error(format string, v …interface{}) {
if LevelError > ll.level {
return
}
ll.p.JobQueue <- func() {
ll.err.Output(ll.depth, fmt.Sprintf(format, v…))
}
}
我们只封装了一层，所以深度设置成3就可以了。



线程安全
原生包打印日志是线程安全的：



func (l *Logger) Output(calldepth int, s string) error {
now := time.Now() // get this early.
var file string
var line int
l.mu.Lock() // 看到这里了么？
defer l.mu.Unlock()
if l.flag&(Lshortfile|Llongfile) != 0 {
// release lock while getting caller info - it’s expensive.
l.mu.Unlock()
var ok bool
_, file, line, ok = runtime.Caller(calldepth)
if !ok {
file = “???”
line = 0
}
l.mu.Lock()
}
l.buf = l.buf[:0]
l.formatHeader(&l.buf, now, file, line)
l.buf = append(l.buf, s…)
if len(s) == 0 || s[len(s)-1] != ‘\n’ {
l.buf = append(l.buf, ‘\n’)
}
_, err := l.out.Write(l.buf)
return err
}
有它的保证，我们也不需要考虑线程安全的问题了。



那么问题来了，fmt包打印日志是线程安全的么？println安全么？fmt和println打印日志都打印到了哪里？有兴趣的可以留言一下一起讨论。



最后
日志的打印会用到诸如fmt.Sprintf的东西，这个在实现的时候将会用到反射。反射会对性能有影响，但是不用反射的话代码过于恶心。



完整的代码放到了 GitHub 上面，地址。



上面介绍的日志只是在针对输出到文件。如果你想输出有邮件、ElasticSearch等其它地方，不要在初始化的时候通过各种复杂配置参数来实现。



我说的是这样：



NewLogger(“es”, …)
NewLogger(“smtp”, …)
这样做的问题就是，我只能用你提供好的东西，如果想扩展只能修改日志包了。如果这个包是第三方的包，那让别人怎么扩展呢？而且这种实现也不是 Golang 的实现风格。



其实大家看看原生的这些包，很多都是通过接口串联起来的。原生的 log 包，你可以认为他提供的服务主要是流程方面的服务，拼接好要打印的内容，包括行号、时间等等，保证线程安全，然后调用Writer来打印。如果我们要把日志打印到 ES 里面，就实现一个ESWriter。这才是 Golang 风格的代码。


Category golang