Go开发关键技术指南：Logger

Logger

一直在码代码，对日志的理解总是不断在变，大致分为几个阶段：

  • 日志是给人看的，是用来查问题的。出现问题后根据某些条件，去查不同进程或服务的日志。日志的关键是不能漏掉信息，漏了关键日志，可能就断了关键的线索。
  • 日志必须要被关联起来，上下文的日志比单个日志更重要。长连接需要根据会话关联日志；不同业务模型有不同的上下文，比如服务器管理把服务器作为关键信息，查询这个服务器的相关日志；全链路跨机器和服务的日志跟踪，需要定义可追踪的逻辑ID。
  • 海量日志是给机器看的，是结构化的，能主动报告问题，能从日志中分析潜在的问题。日志的关键是要被不同消费者消费，要输出不同主题的日志，不同的粒度的日志。日志可以用于排查问题，可以用于告警，可以用于分析业务情况。

Note: 推荐阅读Kafka对于Log的定义，广义日志是可以理解的消息，The Log: What every software engineer should know about real-time data's unifying abstraction。

完善信息查问题

考虑一个服务，处理不同的连接的请求：

package main

import (
    "context"
    "fmt"
    "log"
    "math/rand"
    "os"
    "time"
)

type Connection struct {
    url    string
    logger *log.Logger
}

func (v *Connection) Process(ctx context.Context) {
    go checkRequest(ctx, v.url)

    duration := time.Duration(rand.Int()%1500) * time.Millisecond
    time.Sleep(duration)
    v.logger.Println("Process connection ok")
}

func checkRequest(ctx context.Context, url string) {
    duration := time.Duration(rand.Int()%1500) * time.Millisecond
    time.Sleep(duration)
    logger.Println("Check request ok")
}

var logger *log.Logger

func main() {
    ctx := context.Background()

    rand.Seed(time.Now().UnixNano())
    logger = log.New(os.Stdout, "", log.LstdFlags)

    for i := 0; i < 5; i++ {
        go func(url string) {
            connecton := &Connection{}
            connecton.url = url
            connecton.logger = logger
            connecton.Process(ctx)
        }(fmt.Sprintf("url #%v", i))
    }

    time.Sleep(3 * time.Second)
}

这个日志的主要问题，就是有了和没有差不多，啥也看不出来，常量太多变量太少，缺失了太多的信息。看起来这是个简单问题，却经常容易犯这种问题，需要我们在打印每个日志时，需要思考这个日志比较完善的信息是什么。上面程序输出的日志如下：

2019/11/21 17:08:04 Check request ok
2019/11/21 17:08:04 Check request ok
2019/11/21 17:08:04 Check request ok
2019/11/21 17:08:04 Process connection ok
2019/11/21 17:08:05 Process connection ok
2019/11/21 17:08:05 Check request ok
2019/11/21 17:08:05 Process connection ok
2019/11/21 17:08:05 Check request ok
2019/11/21 17:08:05 Process connection ok
2019/11/21 17:08:05 Process connection ok

如果完善下上下文信息，代码可以改成这样：

type Connection struct {
    url    string
    logger *log.Logger
}

func (v *Connection) Process(ctx context.Context) {
    go checkRequest(ctx, v.url)

    duration := time.Duration(rand.Int()%1500) * time.Millisecond
    time.Sleep(duration)
    v.logger.Println(fmt.Sprintf("Process connection ok, url=%v, duration=%v", v.url, duration))
}

func checkRequest(ctx context.Context, url string) {
    duration := time.Duration(rand.Int()%1500) * time.Millisecond
    time.Sleep(duration)
    logger.Println(fmt.Sprintf("Check request ok, url=%v, duration=%v", url, duration))
}

输出的日志如下：

2019/11/21 17:11:35 Check request ok, url=url #3, duration=32ms
2019/11/21 17:11:35 Check request ok, url=url #0, duration=226ms
2019/11/21 17:11:35 Process connection ok, url=url #0, duration=255ms
2019/11/21 17:11:35 Check request ok, url=url #4, duration=396ms
2019/11/21 17:11:35 Check request ok, url=url #2, duration=449ms
2019/11/21 17:11:35 Process connection ok, url=url #2, duration=780ms
2019/11/21 17:11:35 Check request ok, url=url #1, duration=1.01s
2019/11/21 17:11:36 Process connection ok, url=url #4, duration=1.099s
2019/11/21 17:11:36 Process connection ok, url=url #3, duration=1.207s
2019/11/21 17:11:36 Process connection ok, url=url #1, duration=1.257s

上下文关联

完善日志信息后，对于服务器特有的一个问题，就是如何关联上下文，常见的上下文包括：

  • 如果是短连接，一条日志就能描述，那可能要将多个服务的日志关联起来，将全链路的日志作为上下文。
  • 如果是长连接，一般长连接一定会有定时信息，比如每隔5秒输出这个链接的码率和包数，这样每个链接就无法使用一条日志描述了，链接本身就是一个上下文。
  • 进程内的逻辑上下文，比如代理的上下游就是一个上下文，合并回源，故障上下文，客户端重试等。

以上面的代码为例，可以用请求URL来作为上下文，


package main

import (
    "context"
    "fmt"
    "log"
    "math/rand"
    "os"
    "time"
)

type Connection struct {
    url    string
    logger *log.Logger
}

func (v *Connection) Process(ctx context.Context) {
    go checkRequest(ctx, v.url)

    duration := time.Duration(rand.Int()%1500) * time.Millisecond
    time.Sleep(duration)
    v.logger.Println(fmt.Sprintf("Process connection ok, duration=%v", duration))
}

func checkRequest(ctx context.Context, url string) {
    duration := time.Duration(rand.Int()%1500) * time.Millisecond
    time.Sleep(duration)
    logger.Println(fmt.Sprintf("Check request ok, url=%v, duration=%v", url, duration))
}

var logger *log.Logger

func main() {
    ctx := context.Background()

    rand.Seed(time.Now().UnixNano())
    logger = log.New(os.Stdout, "", log.LstdFlags)

    for i := 0; i < 5; i++ {
        go func(url string) {
            connecton := &Connection{}
            connecton.url = url
            connecton.logger = log.New(os.Stdout, fmt.Sprintf("[CONN %v] ", url), log.LstdFlags)
            connecton.Process(ctx)
        }(fmt.Sprintf("url #%v", i))
    }

    time.Sleep(3 * time.Second)
}

运行结果如下所示：

[CONN url #2] 2019/11/21 17:19:28 Process connection ok, duration=39ms
2019/11/21 17:19:28 Check request ok, url=url #0, duration=149ms
2019/11/21 17:19:28 Check request ok, url=url #1, duration=255ms
[CONN url #3] 2019/11/21 17:19:28 Process connection ok, duration=409ms
2019/11/21 17:19:28 Check request ok, url=url #2, duration=408ms
[CONN url #1] 2019/11/21 17:19:29 Process connection ok, duration=594ms
2019/11/21 17:19:29 Check request ok, url=url #4, duration=615ms
[CONN url #0] 2019/11/21 17:19:29 Process connection ok, duration=727ms
2019/11/21 17:19:29 Check request ok, url=url #3, duration=1.105s
[CONN url #4] 2019/11/21 17:19:29 Process connection ok, duration=1.289s

如果需要查连接2的日志，可以grep这个url #2关键字：

Mac:gogogo chengli.ycl$ grep 'url #2' t.log
[CONN url #2] 2019/11/21 17:21:43 Process connection ok, duration=682ms
2019/11/21 17:21:43 Check request ok, url=url #2, duration=998ms

燃鹅，还是发现有不少问题：

  • 如何实现隐式标识，调用时如何简单些，不用没打一条日志都需要传一堆参数？
  • 一般logger是公共函数（或者是每个类一个logger），而上下文的生命周期会比logger长，比如checkRequest是个全局函数，标识信息必须依靠人打印，这往往是不可行的。
  • 如何实现日志的logrotate(切割和轮转)，如何收集多个服务器日志。

解决办法包括：

  • 用Context的WithValue来将上下文相关的ID保存，在打印日志时将ID取出来。
  • 如果有业务特征，比如可以取SessionID的hash的前8个字符形成ID，虽然容易碰撞，但是在一定范围内不容易碰撞。
  • 可以变成json格式的日志，这样可以将level、id、tag、file、err都变成可以程序分析的数据，送到SLS中处理。
  • 对于切割和轮转，推荐使用lumberjack这个库，程序的logger只要提供SetOutput(io.Writer)将日志送给它处理就可以了。

当然，这要求函数传参时需要带context.Context，一般在自己的应用程序中可以要求这么做，凡是打日志的地方要带context。对于库，一般可以不打日志，而返回带堆栈的复杂错误的方式，参考Errors错误处理部分。

Links

由于简书限制了文章字数，只好分成不同章节：

  • Overview 为何Go有时候也叫Golang?为何要选择Go作为服务器开发的语言？是冲动？还是骚动？Go的重要里程碑和事件，当年吹的那些牛逼，都实现了哪些？
  • Could Not Recover 君可知，有什么panic是无法recover的？包括超过系统线程限制，以及map的竞争写。当然一般都能recover，比如Slice越界、nil指针、除零、写关闭的chan等。
  • Errors 为什么Go2的草稿3个有2个是关于错误处理的？好的错误处理应该怎么做？错误和异常机制的差别是什么？错误处理和日志如何配合？
  • Logger 为什么标准库的Logger是完全不够用的？怎么做日志切割和轮转？怎么在混成一坨的服务器日志中找到某个连接的日志？甚至连接中的流的日志？怎么做到简洁又够用？
  • Interfaces 什么是面向对象的SOLID原则？为何Go更符合SOLID？为何接口组合比继承多态更具有正交性？Go类型系统如何做到looser, organic, decoupled, independent, and therefore scalable？一般软件中如果出现数学，要么真的牛逼要么装逼。正交性这个数学概念在Go中频繁出现，是神仙还是妖怪？为何接口设计要考虑正交性？
  • Modules 如何避免依赖地狱(Dependency Hell)？小小的版本号为何会带来大灾难？Go为什么推出了GOPATH、Vendor还要搞module和vgo？新建了16个仓库做测试，碰到了9个坑，搞清楚了gopath和vendor如何迁移，以及vgo with vendor如何使用（毕竟生产环境不能每次都去外网下载）。
  • Concurrency & Control 服务器中的并发处理难在哪里？为什么说Go并发处理优势占领了云计算开发语言市场？什么是C10K、C10M问题？如何管理goroutine的取消、超时和关联取消？为何Go1.7专门将context放到了标准库？context如何使用，以及问题在哪里？
  • Engineering Go在工程化上的优势是什么？为什么说Go是一门面向工程的语言？覆盖率要到多少比较合适？什么叫代码可测性？为什么良好的库必须先写Example？
  • Go2 Transition Go2会像Python3不兼容Python2那样作吗？C和C++的语言演进可以有什么不同的收获？Go2怎么思考语言升级的问题？
  • SRS & Others Go在流媒体服务器中的使用。Go的GC靠谱吗？Twitter说相当的靠谱，有图有真相。为何Go的声明语法是那样？C的又是怎样？是拍的大腿，还是拍的脑袋？
最后编辑于 ：
©著作权归作者所有,转载或内容合作请联系作者
禁止转载，如需转载请通过简信或评论联系作者。
  • 人面猴
    序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
    沈念sama阅读 204,445评论 6赞 478
  • 死咒
    序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
    沈念sama阅读 85,889评论 2赞 381
  • 救了他两次的神仙让他今天三更去死
    文/潘晓璐 我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
    开封第一讲书人阅读 151,047评论 0赞 337
  • 道士缉凶录：失踪的卖姜人
    文/不坏的土叔 我叫张陵，是天一观的道长。 经常有香客问我，道长，这世上最难降的妖魔是什么？ 我笑而不...
    开封第一讲书人阅读 54,760评论 1赞 276
  • 港岛之恋（遗憾婚礼）
    正文 为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
    茶点故事阅读 63,745评论 5赞 367
  • 恶毒庶女顶嫁案：这布局不是一般人想出来的
    文/花漫 我一把揭开白布。 她就那样静静地躺着，像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上，一...
    开封第一讲书人阅读 48,638评论 1赞 281
  • 城市分裂传说
    那天，我揣着相机与录音，去河边找鬼。 笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。 我是一名探鬼主播，决...
    沈念sama阅读 38,011评论 3赞 398
  • 双鸳鸯连环套：你想象不到人心有多黑
    文/苍兰香墨 我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
    开封第一讲书人阅读 36,669评论 0赞 258
  • 万荣杀人案实录
    序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
    沈念sama阅读 40,923评论 1赞 299
  • 护林员之死
    正文 独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,655评论 2赞 321
  • 白月光启示录
    正文 我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,740评论 1赞 330
  • 活死人
    序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
    沈念sama阅读 33,406评论 4赞 320
  • 日本核电站爆炸内幕
    正文 年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
    茶点故事阅读 38,995评论 3赞 307
  • 男人毒药：我在死后第九天来索命
    文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,961评论 0赞 19
  • 一桩弑父案，背后竟有这般阴谋
    文/苍兰香墨 我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,197评论 1赞 260
  • 情欲美人皮
    我被黑心中介骗来泰国打工， 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。 一个月前我还...
    沈念sama阅读 45,023评论 2赞 350
  • 代替公主和亲
    正文 我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
    茶点故事阅读 42,483评论 2赞 342

推荐阅读更多精彩内容