原文

Go 开发关键技术指南 | Go 面向失败编程 (内含超全知识大图）-阿里云开发者社区 (aliyun.com) (opens new window)

Could Not Recover

哪些可以 Recover

Go 有 Defer, Panic, and Recover (opens new window)。其中 defer 一般用在资源释放或者捕获 panic。而 panic 是中止正常的执行流程，执行所有的 defer，返回调用函数继续 panic；主动调用 panic 函数，还有些运行时错误都会进入 panic 过程。最后 recover 是在 panic 时获取控制权，进入正常的执行逻辑。

注意 recover 只有在 defer 函数中才有用，在 defer 的函数调用的函数中 recover 不起作用，如下实例代码不会 recover：

package main

import "fmt"

func main() {
    f := func() {
        if r := recover(); r != nil {
            fmt.Println(r)
        }
    }
    defer func() {
        f()
    } ()
    panic("ok")
}

有些情况是不可以被捕获，程序会自动退出，这种都是无法正常 recover。当然，一般的 panic 都是能捕获的，比如 Slice 越界、nil 指针、除零、写关闭的 chan。

Recover 最佳实践

一般 recover 后会判断是否 err，有可能需要处理特殊的 error，一般也需要打印日志或者告警

对于库如果需要启动 goroutine，如何 recover 呢？

• 如果不可能出现 panic，可以不用 recover，比如 tls.go 中的一个 goroutine：errChannel <- conn.Handshake() ；
• 如果可能出现 panic，也比较明确的可以 recover，可以调用用户回调，或者让用户设置 logger，比如 http/server.go 处理请求的 goroutine：if err := recover(); err != nil && err != ErrAbortHandler { ；
• 如果完全不知道如何处理 recover，比如一个 cache 库，丢弃数据可能会造成问题，那么就应该由用户来启动 goroutine，返回异常数据和错误，用户决定如何 recover、如何重试；
• 如果完全知道如何 recover，比如忽略 panic 继续跑，或者能使用 logger 打印日志，那就按照正常的 panic-recover 逻辑处理。

哪些不能recover

下面看看一些情况是无法捕获的，包括（不限于）：

• Thread Limit，超过了系统的线程限制，详细参考下面的说明；
• Concurrent Map Writers，竞争条件，同时写 map，参考下面的例子。推荐使用标准库的 sync.Map 解决这个问题。

errors

错误处理是现实中经常碰到的、难以处理好的问题，下面会从下面几个方面探讨错误处理：

• 为什么 Go 没有选择异常，而是返回错误码(error)？ (opens new window) 因为异常模型很难看出有没有写对，错误码方式也不容易，相对会简单点。
• Go 的 error 有什么问题，为何 Go2 草案这么大篇幅说 error 改进？ (opens new window) 因为 Go 虽然是错误码但还不够好，问题在于啰嗦、繁杂、缺失关键信息。
• 有哪些好用的 error 库，如何和日志配合使用？ (opens new window) 推荐用库 pkg/errors (opens new window)；另外，避免日志和错误混淆。
• Go 的错误处理最佳实践是什么？ (opens new window) 配合日志使用错误。错误需要带上上下文、堆栈等信息。

错误和异常

我们总会遇到非预期的非正常情况，有一种是符合预期的，比如函数返回 error 并处理，这种叫做可以预见到的错误，还有一种是预见不到的比如除零、空指针、数组越界等叫做 panic，panic 的处理主要参考 Defer, Panic, and Recover (opens new window)。

错误处理的模型一般有两种，一般是错误码模型比如 C/C++ 和 Go，还有异常模型比如 Java 和 C#。Go 没有选择异常模型，因为错误码比异常更有优势，参考文章《Cleaner, more elegant, and wrong (opens new window)》以及《Cleaner, more elegant, and harder to recognize (opens new window)》。

errors in go

下面这种情况是不推荐的

package main

import (
  "fmt"
  "io"
  "os"
)

func CopyFile(src, dst string) error {
  r, _ := os.Open(src)
  defer r.Close()

  w, _ := os.Create(dst)
  io.Copy(w, r)
  w.Close()

  return nil
}

func main() {
  fmt.Println(CopyFile("src.txt", "dst.txt"))
}

正确的写法是这样

package main

import (
  "fmt"
  "io"
  "os"
)

func CopyFile(src, dst string) error {
  r, err := os.Open(src)
  if err != nil {
    return fmt.Errorf("copy %s %s: %v", src, dst, err)
  }
  defer r.Close()

  w, err := os.Create(dst)
  if err != nil {
    return fmt.Errorf("copy %s %s: %v", src, dst, err)
  }

  if _, err := io.Copy(w, r); err != nil {
    w.Close()
    os.Remove(dst)
    return fmt.Errorf("copy %s %s: %v", src, dst, err)
  }

  if err := w.Close(); err != nil {
    os.Remove(dst)
    return fmt.Errorf("copy %s %s: %v", src, dst, err)
  }
  return nil
}

func main() {
  fmt.Println(CopyFile("src.txt", "dst.txt"))
}

不过这样其实也很麻烦。。。

go1.13改进了errors

package main

import (
    "errors"
    "fmt"
    "io"
)

func foo() error {
    return fmt.Errorf("read err: %w", io.EOF)
}

func bar() error {
    if err := foo(); err != nil {
        return fmt.Errorf("foo err: %w", err)
    }
    return nil
}

func main() {
    if err := bar(); err != nil {
        fmt.Printf("err: %+v\n", err)
        fmt.Printf("unwrap: %+v\n", errors.Unwrap(err))
        fmt.Printf("unwrap of unwrap: %+v\n", errors.Unwrap(errors.Unwrap(err)))
        fmt.Printf("err is io.EOF? %v\n", errors.Is(err, io.EOF))
    }
}

err: foo err: read err: EOF
unwrap: read err: EOF
unwrap of unwrap: EOF
err is io.EOF? true

总结下 Go 的 error，错误处理应该注意以下几点：

• 凡是有返回错误码的函数，必须显式的处理错误，如果要忽略错误，也应该显式的忽略和写注释；
• 错误必须带丰富的错误信息，比如堆栈、发生错误时的参数、调用链给的描述等等。特别要强调变量，我看过太多日志描述了一对常量，比如 "Verify the nonce, timestamp and token of specified appid failed"，而这个消息一般会提到工单中，然后就是再问用户，哪个 session 或 request 甚至时间点？这么一大堆常量有啥用呢，关键是变量呐；
• 尽量避免重复的信息，提高错误处理的开发体验，糟糕的体验会导致无效的错误处理代码，比如拷贝和漏掉关键信息；
• 分离错误和日志，发生错误时返回带完整信息的错误，在调用的顶层决定是将错误用日志打印，还是发送到监控系统，还是转换错误，或者忽略。

最佳实践

推荐用 github.com/pkg/errors (opens new window) 这个错误处理的库，基本上是够用的，参考 Refine: CopyFile，可以看到 CopyFile 中低级重复的代码已经比较少了：

package main

import (
  "fmt"
  "github.com/pkg/errors"
  "io"
  "os"
)

func CopyFile(src, dst string) error {
  r, err := os.Open(src)
  if err != nil {
    return errors.Wrap(err, "open source")
  }
  defer r.Close()

  w, err := os.Create(dst)
  if err != nil {
    return errors.Wrap(err, "create dest")
  }

  nn, err := io.Copy(w, r)
  if err != nil {
    w.Close()
    os.Remove(dst)
    return errors.Wrap(err, "copy body")
  }

  if err := w.Close(); err != nil {
    os.Remove(dst)
    return errors.Wrapf(err, "close dest, nn=%v", nn)
  }

  return nil
}
func LoadSystem() error {
  src, dst := "src.txt", "dst.txt"
  if err := CopyFile(src, dst); err != nil {
    return errors.WithMessage(err, fmt.Sprintf("load src=%v, dst=%v", src, dst))
  }

  // Do other jobs.

  return nil
}

func main() {
  if err := LoadSystem(); err != nil {
    fmt.Printf("err %+v\n", err)
  }
}

改写的函数中，用 errors.Wrap 和 errors.Wrapf 代替了 fmt.Errorf，我们不记录 src 和 dst 的值，因为在上层会记录这个值（参考下面的代码），而只记录我们这个函数产生的数据，比如 nn。

import "github.com/pkg/errors"

func LoadSystem() error {
    src, dst := "src.txt", "dst.txt"
    if err := CopyFile(src, dst); err != nil {
        return errors.WithMessage(err, fmt.Sprintf("load src=%v, dst=%v", src, dst))
    }

    // Do other jobs.

    return nil
}

在这个上层函数中，我们用的是 errors.WithMessage 添加了这一层的错误信息，包括 src 和 dst，所以 CopyFile 里面就不用重复记录这两个数据了。同时我们也没有打印日志，只是返回了带完整信息的错误。

func main() {
    if err := LoadSystem(); err != nil {
        fmt.Printf("err %+v\n", err)
    }
}

在顶层调用时，我们拿到错误，可以决定是打印还是忽略还是送监控系统。

比如我们在调用层打印错误，使用 %+v 打印详细的错误，有完整的信息：

err open src.txt: no such file or directory
open source
main.CopyFile
    /Users/winlin/t.go:13
main.LoadSystem
    /Users/winlin/t.go:39
main.main
    /Users/winlin/t.go:49
runtime.main
    /usr/local/Cellar/go/1.8.3/libexec/src/runtime/proc.go:185
runtime.goexit
    /usr/local/Cellar/go/1.8.3/libexec/src/runtime/asm_amd64.s:2197
load src=src.txt, dst=dst.txt

Logger

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

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

完善信息查问题

先看一个简单例子

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