作者 | 楊成立（忘籬） 阿里巴巴高階技術專家

**關注“阿里巴巴雲原生”公眾號，回覆 Go 即可檢視清晰知識大圖！**

> **導讀**：從問題本身出發，不侷限於 Go 語言，探討伺服器中常常遇到的問題，最後回到 Go 如何解決這些問題，為大家提供 Go 開發的關鍵技術指南。我們將以系列文章的形式推出[《Go 開發的關鍵技術指南》](https://developer.aliyun.com/article/739836)，共有 4 篇文章，本文為第 2 篇。

![go.png](https://ucc.alicdn.com/pic/developer-ecology/6e15f829979442689ce0081e65a2b7b2.png)

## Could Not Recover

在 C/C++ 中，

- **最苦惱的**莫過於上線後發現有野指標或記憶體越界，導致不可能崩潰的地方崩潰；
- **最無語的**是因為很早寫的日誌列印，比如 %s 把整數當字串，突然某天執行到了崩潰；
- **最無奈的**是無論因為什麼崩潰都導致服務的所有使用者受到影響。

如果能有一種方案，將指標和記憶體都管理起來，避免使用者錯誤訪問和釋放，這樣雖然浪費了一部分的 CPU，但是可以在快速變化的業務中避免這些頭疼的問題。在現代的高階語言中，比如 Java、Python 和 JS 的異常，以及 Go 的 panic-recover 都是這種機制。

畢竟，用一些 CPU 換得快速迭代中的不 Crash，怎麼算都是划得來的。

### 哪些可以 Recover

Go 有 [Defer, Panic, and Recover](https://blog.golang.org/defer-panic-and-recover)。其中 defer 一般用在資源釋放或者捕獲 panic。而 panic 是中止正常的執行流程，執行所有的 defer，返回撥用函式繼續 panic；主動呼叫 panic 函式，還有些執行時錯誤都會進入 panic 過程。最後 recover 是在 panic 時獲取控制權，進入正常的執行邏輯。

注意 recover 只有在 defer 函式中才有用，在 defer 的函式呼叫的函式中 recover 不起作用，如下例項程式碼不會 recover：

```
go
package main

import "fmt"

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

defer func() {
		f()
	} ()

panic("ok")
}
```

執行時依舊會 panic，結果如下：

```
$ go run t.go 
panic: ok

goroutine 1 [running]:
main.main()
	/Users/winlin/temp/t.go:16 +0x6b
exit status 2
```

有些情況是不可以被捕獲，程式會自動退出，這種都是無法正常 recover。當然，一般的 panic 都是能捕獲的，比如 Slice 越界、nil 指標、除零、寫關閉的 chan。

下面是 Slice 越界的例子，recover 可以捕獲到：

```
go
package main

import (
  "fmt"
)

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

b := []int{0, 1}
  fmt.Println("Hello, playground", b[2])
}
```

下面是 nil 指標被引用的例子，recover 可以捕獲到：

```
go
package main

import (
  "bytes"
  "fmt"
)

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

var b *bytes.Buffer
  fmt.Println("Hello, playground", b.Bytes())
}
```

下面是除零的例子，recover 可以捕獲到：

```
go
package main

import (
  "fmt"
)

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

var v int
  fmt.Println("Hello, playground", 1/v)
}
```

下面是寫關閉的 chan 的例子，recover 可以捕獲到：

```
go
package main

import (
  "fmt"
)

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

c := make(chan bool)
  close(c)
  c  注意：如果編譯時加了 `-race`，其他競爭條件也會退出，一般用於死鎖檢測，但這會導致嚴重的效能問題，使用需要謹慎。

> 備註：一般標準庫中透過 `throw` 丟擲的錯誤都是無法 recover 的，搜尋了下 Go1.11 一共有 690 個地方有呼叫 throw。

Go1.2 引入了能使用的最多執行緒數限制 [ThreadLimit](https://golang.org/doc/go1.2#thread_limit)，如果超過了就 panic，這個 panic 是無法 recover 的。

```
fatal error: thread exhaustion

runtime stack:
runtime.throw(0x10b60fd, 0x11)
	/usr/local/Cellar/go/1.8.3/libexec/src/runtime/panic.go:596 +0x95
runtime.mstart()
	/usr/local/Cellar/go/1.8.3/libexec/src/runtime/proc.go:1132
```

預設是 1 萬個物理執行緒，我們可以呼叫 `runtime` 的 [`debug.SetMaxThreads`](https://golang.org/pkg/runtime/debug/#SetMaxThreads) 設定最大執行緒數。

> SetMaxThreads sets the maximum number of operating system threads that the Go program can use. If it attempts to use more than this many, the program crashes. SetMaxThreads returns the previous setting. The initial setting is 10,000 threads.

用這個函式設定程式能使用的最大系統執行緒數，如果超過了程式就 crash，返回的是之前設定的值，預設是 1 萬個執行緒。

> The limit controls the number of operating system threads, not the number of goroutines. A Go program creates a new thread only when a goroutine is ready to run but all the existing threads are blocked in system calls, cgo calls, or are locked to other goroutines due to use of runtime.LockOSThread.

注意限制的並不是 goroutine 的數目，而是使用的系統執行緒的限制。goroutine 啟動時，並不總是新開系統執行緒，只有當目前所有的物理執行緒都阻塞在系統呼叫、cgo 呼叫，或者顯示有呼叫 `runtime.LockOSThread` 時。

> SetMaxThreads is useful mainly for limiting the damage done by programs that create an unbounded number of threads. The idea is to take down the program before it takes down the operating system.

這個是最後的防禦措施，可以在程式乾死系統前把有問題的程式幹掉。

舉一個簡單的例子，限制使用 10 個執行緒，然後用 `runtime.LockOSThread` 來繫結 goroutine 到系統執行緒，可以看到沒有建立 10 個 goroutine 就退出了（runtime 也需要使用執行緒）。參考下面的例子 Playground: ThreadLimit：

```
go
package main

import (
  "fmt"
  "runtime"
  "runtime/debug"
  "sync"
  "time"
)

func main() {
  nv := 10
  ov := debug.SetMaxThreads(nv)
  fmt.Println(fmt.Sprintf("Change max threads %d=>%d", ov, nv))

var wg sync.WaitGroup
  c := make(chan bool, 0)
  for i := 0; i < 10; i++ {
    fmt.Println(fmt.Sprintf("Start goroutine #%v", i))

wg.Add(1)
    go func() {
      c 10
Start goroutine #0
Start goroutine #0 ok
......
Start goroutine #6
Start goroutine #6 ok
Start goroutine #7
runtime: program exceeds 10-thread limit
fatal error: thread exhaustion

runtime stack:
runtime.throw(0xffdef, 0x11)
	/usr/local/go/src/runtime/panic.go:616 +0x100
runtime.checkmcount()
	/usr/local/go/src/runtime/proc.go:542 +0x100
......
	/usr/local/go/src/runtime/proc.go:1830 +0x40
runtime.startm(0x1040e000, 0x1040e000)
	/usr/local/go/src/runtime/proc.go:2002 +0x180
```

從這次執行可以看出，限制可用的物理執行緒為 10 個，其中系統佔用了 3 個物理執行緒，user-level 可執行 7 個執行緒，開啟第 8 個執行緒時就崩潰了。

> 注意這個執行結果在不同的 go 版本是不同的，比如 Go1.8 有時候啟動 4 到 5 個 goroutine 就會崩潰。

而且加 recover 也無法恢復，參考下面的例項程式碼。

可見這個機制是最後的防禦，不能突破的底線。我們線上上服務時，曾經因為 block 的 goroutine 過多，導致觸發了這個機制。

```
go
package main

import (
  "fmt"
  "runtime"
  "runtime/debug"
  "sync"
  "time"
)

func main() {
  defer func() {
    if r := recover(); r != nil {
      fmt.Println("main recover is", r)
    }
  } ()

nv := 10
  ov := debug.SetMaxThreads(nv)
  fmt.Println(fmt.Sprintf("Change max threads %d=>%d", ov, nv))

var wg sync.WaitGroup
  c := make(chan bool, 0)
  for i := 0; i < 10; i++ {
    fmt.Println(fmt.Sprintf("Start goroutine #%v", i))

wg.Add(1)
    go func() {
      c  The GOMAXPROCS variable limits the number of operating system threads that can execute user-level Go code simultaneously. There is no limit to the number of threads that can be blocked in system calls on behalf of Go code; those do not count against the GOMAXPROCS limit. This package's GOMAXPROCS function queries and changes the limit.

> GOMAXPROCS sets the maximum number of CPUs that can be executing simultaneously and returns the previous setting. If n < 1, it does not change the current setting. The number of logical CPUs on the local machine can be queried with NumCPU. This call will go away when the scheduler improves.

可見 GOMAXPROCS 只是設定 user-level 並行執行的執行緒數，也就是真正執行的執行緒數 。實際上如果物理執行緒阻塞在 system calls，會開啟更多的物理執行緒。關於這個引數的說明，文章《[Number of threads used by goroutine](https://stackoverflow.com/questions/39245660/number-of-threads-used-by-go-runtime)》解釋得很清楚：

> There is no direct correlation. Threads used by your app may be less than, equal to or more than 10.

> So if your application does not start any new goroutines, threads count will be less than 10.

> If your app starts many goroutines (>10) where none is blocking (e.g. in system calls), 10 operating system threads will execute your goroutines simultaneously.

> If your app starts many goroutines where many (>10) are blocked in system calls, more than 10 OS threads will be spawned (but only at most 10 will be executing user-level Go code).

設定 GOMAXPROCS 為 10：如果開啟的 goroutine 小於 10 個，那麼物理執行緒也小於 10 個。如果有很多 goroutines，但是沒有阻塞在 system calls，那麼只有 10 個執行緒會並行執行。如果有很多 goroutines 同時超過 10 個阻塞在 system calls，那麼超過 10 個物理執行緒會被建立，但是隻有 10 個活躍的執行緒執行 user-level 程式碼。

那麼什麼時候會阻塞在 system blocking 呢？例子《[Why does it not create many threads when many goroutines are blocked in writing](https://stackoverflow.com/questions/28186361/why-does-it-not-create-many-threads-when-many-goroutines-are-blocked-in-writing)》解釋很清楚，雖然設定了 GOMAXPROCS 為 1，但實際上還是開啟了 12 個執行緒，每個 goroutine 一個物理執行緒，具體執行下面的程式碼 Writing Large Block：

```
go
package main

import (
  "io/ioutil"
  "os"
  "runtime"
  "strconv"
  "sync"
)

func main() {
  runtime.GOMAXPROCS(1)
  data := make([]byte, 128*1024*1024)

var wg sync.WaitGroup
  for i := 0; i < 10; i++ {
    wg.Add(1)
    go func(n int) {
      defer wg.Done()
      for {
        ioutil.WriteFile("testxxx"+strconv.Itoa(n), []byte(data), os.ModePerm)
      }
    }(i)
  }

wg.Wait()
}
```

執行結果如下：

```bash
Mac chengli.ycl$ time go run t.go
real	1m44.679s
user	0m0.230s
sys	0m53.474s
```

> 雖然 GOMAXPROCS 設定為 1，實際上建立了 12 個物理執行緒。

> 有大量的時間是在 sys 上面，也就是 system calls。

> So I think the syscalls were exiting too quickly in your original test to show the effect you were expecting.

[Effective Go](https://golang.org/doc/effective_go.html#goroutines) 中的解釋:

> Goroutines are multiplexed onto multiple OS threads so if one should block, such as while waiting for I/O, others continue to run. Their design hides many of the complexities of thread creation and management.

由此可見，如果程式出現因為超過執行緒限制而崩潰，那麼可以在出現瓶頸時，用 linux 工具檢視系統呼叫的統計，看哪些系統呼叫導致建立了過多的執行緒。

## Errors

錯誤處理是現實中經常碰到的、難以處理好的問題，下面會從下面幾個方面探討錯誤處理：

- [為什麼 Go 沒有選擇異常，而是返回錯誤碼(error)？](#errors-pk-exceptions) 因為異常模型很難看出有沒有寫對，錯誤碼方式也不容易，相對會簡單點。
- [Go 的 error 有什麼問題，為何 Go2 草案這麼大篇幅說 error 改進？](#errors-in-go) 因為 Go 雖然是錯誤碼但還不夠好，問題在於囉嗦、繁雜、缺失關鍵資訊。
- [有哪些好用的 error 庫，如何和日誌配合使用？](#errors-solutions) 推薦用庫 [pkg/errors](https://github.com/pkg/errors)；另外，避免日誌和錯誤混淆。
- [Go 的錯誤處理最佳實踐是什麼？](#errors-best-practice) 配合日誌使用錯誤。錯誤需要帶上上下文、堆疊等資訊。

### 錯誤和異常

我們總會遇到非預期的非正常情況，有一種是符合預期的，比如函式返回 error 並處理，這種叫做可以預見到的錯誤，還有一種是預見不到的比如除零、空指標、陣列越界等叫做 panic，panic 的處理主要參考 [Defer, Panic, and Recover](https://blog.golang.org/defer-panic-and-recover)。

錯誤處理的模型一般有兩種，一般是錯誤碼模型比如 C/C++ 和 Go，還有異常模型比如 Java 和 C#。Go 沒有選擇異常模型，因為錯誤碼比異常更有優勢，參考文章《[Cleaner, more elegant, and wrong](https://blogs.msdn.microsoft.com/oldnewthing/20040422-00/?p=39683)》以及《[Cleaner, more elegant, and harder to recognize](https://blogs.msdn.microsoft.com/oldnewthing/20050114-00/?p=36693)》。

看下面的程式碼：

```
try {
  AccessDatabase accessDb = new AccessDatabase();
  accessDb.GenerateDatabase();
} catch (Exception e) {
  // Inspect caught exception
}

public void GenerateDatabase()
{
  CreatePhysicalDatabase();
  CreateTables();
  CreateIndexes();
}
```

這段程式碼的錯誤處理有很多問題，比如如果 `CreateIndexes` 丟擲異常，會導致資料庫和表不會刪除，造成髒資料。從程式碼編寫者和維護者的角度看這兩個模型，會比較清楚：

![_1](https://yqfile.alicdn.com/92bd3a63896ae8648d0368e6847b14cc50ed113e.png)

> 錯誤處理不容易做好，要說容易那說明做錯了；要把錯誤處理寫對了，基於錯誤碼模型雖然很難，但比異常模型簡單。

![_2](https://yqfile.alicdn.com/8398eaf8a59b77042ea5a8aa72452bcd2f99cd76.png)

> 如果使用錯誤碼模型，非常容易就能看出錯誤處理沒有寫對，也能很容易知道做得好不好；要知道是否做得非常好，錯誤碼模型也不太容易。
> 
> 如果使用異常模型，無論做的好不好都很難知道，而且也很難知道怎麼做好。

<a name="19daca20" rel="nofollow"></a>
### Errors in Go

Go 官方的 error 介紹，簡單一句話就是返回錯誤物件的方式，參考《[Error handling and Go](https://blog.golang.org/error-handling-and-go)》，解釋了 error 是什麼？如何判斷具體的錯誤？以及顯式返回錯誤的好處。

文中舉的例子就是開啟檔案錯誤：

```
func Open(name string) (file *File, err error)
```

Go 可以返回多個值，最後一個一般是 error，我們需要檢查和處理這個錯誤，這就是 Go 的錯誤處理的官方介紹：

```
if err := Open("src.txt"); err != nil {
    // Handle err
}
```

看起來非常簡單的錯誤處理，有什麼難的呢？稍等，在 Go2 的草案中，提到的三個點 [Error Handling](https://go.googlesource.com/proposal/+/master/design/go2draft-error-handling-overview.md)、[Error Values](https://go.googlesource.com/proposal/+/master/design/go2draft-error-values-overview.md)和 [Generics 泛型](https://go.googlesource.com/proposal/+/master/design/go2draft-generics-overview.md)，兩個點都是錯誤處理的，這說明了 Go1 中對於錯誤是有改進的地方。

再詳細看下 Go2 的草案，[錯誤處理：Error Handling](https://go.googlesource.com/proposal/+/master/design/go2draft-error-handling-overview.md) 中，主要描述了發生錯誤時的重複程式碼，以及不能便捷處理錯誤的情況。比如草案中舉的這個例子 No Error Handling: CopyFile，沒有做任何錯誤處理：

```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"))
}
```

還有草案中這個例子 Not Nice and still Wrong: CopyFile，錯誤處理是特別囉嗦，而且比較明顯有問題：

```go
package main

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

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

w, err := os.Create(dst)
  if err != nil {
    return err
  }
  defer w.Close()

if _, err := io.Copy(w, r); err != nil {
    return err
  }
  if err := w.Close(); err != nil {
    return err
  }
  return nil
}

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

當 `io.Copy` 或 `w.Close` 出現錯誤時，目標檔案實際上是有問題，那應該需要刪除 dst 檔案的。而且需要給出錯誤時的資訊，比如是哪個檔案，不能直接返回 err。所以 Go 中正確的錯誤處理，應該是這個例子 Good: CopyFile，雖然囉嗦繁瑣不簡潔：

```go
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"))
}
```

> 具體應該如何簡潔的處理錯誤，可以讀 [Error Handling](https://go.googlesource.com/proposal/+/master/design/go2draft-error-handling-overview.md)，大致是引入關鍵字 handle 和 check，由於本文重點側重 Go1 如何錯誤處理，就不展開分享了。

明顯上面每次都返回的 `fmt.Errorf` 資訊也是不夠的，所以 Go2 還對於錯誤的值有提案，參考 [Error Values](https://go.googlesource.com/proposal/+/master/design/go2draft-error-values-overview.md)。大規模程式應該面向錯誤程式設計和測試，同時錯誤應該包含足夠的資訊。

Go1 中判斷 error 具體是什麼錯誤，有以下幾種辦法：

- 直接比較，比如返回的是 `io.EOF` 這個全域性變數，那麼可以直接比較是否是這個錯誤；
- 可以用型別轉換 type 或 switch，嘗試來轉換成具體的錯誤型別，看是哪種錯誤；
- 提供某些函式來判斷是否是某個錯誤，比如 `os.IsNotExist` 判斷是否是指定錯誤；
- 當多個錯誤被糅合到一起時，只能用 `error.Error()` 返回的字串匹配，看是否是某個錯誤。

在複雜程式中，有用的錯誤需要包含呼叫鏈的資訊。例如，考慮一次資料庫寫，可能呼叫了 RPC，RPC 呼叫了域名解析，最終是沒有許可權讀 `/etc/resolve.conf` 檔案，那麼給出下面的呼叫鏈會非常有用：

```
write users database: call myserver.Method: \
    dial myserver:3333: open /etc/resolv.conf: permission denied
```

<a name="43f7325f" rel="nofollow"></a>
### Errors Solutions

由於 Go1 的錯誤值沒有完整的解決這個問題，才導致出現非常多的錯誤處理的庫，比如：

- 2017 年 12 月, upspin.io/errors，帶邏輯呼叫堆疊的錯誤庫，而不是執行的堆疊，引入了 `errors.Is`、`errors.As` 和 `errors.Match`；
- 2015 年 12 月, github.com/pkg/errors，帶堆疊的錯誤，引入了 `%+v` 來格式化錯誤的額外資訊比如堆疊；
- 2014 年 10 月, github.com/hashicorp/errwrap，可以 wrap 多個錯誤，引入了錯誤樹，提供 Walk 函式遍歷所有的錯誤；
- 2014 年 2 月, github.com/juju/errgo，Wrap 時可以選擇是否隱藏底層錯誤。和 `pkg/errors` 的 Cause 返回最底層的錯誤不同，它只反饋錯誤鏈的下一個錯誤；
- 2013 年 7 月, github.com/spacemonkeygo/errors，是來源於一個大型 Python 專案，有錯誤的 hierarchies，自動記錄日誌和堆疊，還可以帶額外的資訊。列印錯誤的訊息比較固定，不能自己定義；
- 2019 年 9 月，[Go1.13](https://blog.golang.org/go1.13-errors) 標準庫擴充套件了 error，支援了 Unwrap、As 和 Is，但沒有支援堆疊資訊。

Go1.13 改進了 errors，參考如下例項程式碼：

```go
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
```

從上面的例子可以看出：

- 沒有堆疊資訊，主要是想透過 Wrap 的日誌來標識堆疊，如果全部 Wrap 一層和堆疊差不多，不過對於沒有 Wrap 的錯誤還是無法知道呼叫堆疊；
- Unwrap 只會展開第一個巢狀的 error，如果錯誤有多層巢狀，取不到最裡面的那個 error，需要多次 Unwrap 才行；
- 用 `errors.Is` 能判斷出是否是最裡面的那個 error。

另外，錯誤處理往往和 log 是容易混為一談的，因為遇到錯誤一般會打日誌，特別是在 C/C 中返回錯誤碼一般都會打日誌記錄下，有時候還會記錄一個全域性的錯誤碼比如 linux 的 errno，而這種習慣，導致 error 和 log 混淆造成比較大的困擾。考慮以前寫了一個 C 的伺服器，出現錯誤時會在每一層列印日誌，所以就會形成堆疊式的錯誤日誌，便於排查問題，如果只有一個錯誤，不知道呼叫上下文，排查會很困難：

```
avc decode avc_packet_type failed. ret=3001
Codec parse video failed, ret=3001
origin hub error, ret=3001
```

這種比只列印一條日誌 `origin hub error, ret=3001` 要好，但是還不夠好：

- 和 Go 的錯誤一樣，比較囉嗦，有重複的資訊。如果能提供堆疊資訊，可以省去很多需要手動寫的資訊；
- 對於應用程式可以打日誌，但是對於庫，資訊都應該包含在 error 中，不應該直接列印日誌。如果底層的庫都要列印日誌，將會導致底層庫都要依賴日誌庫，這時很多庫都有日誌列印函式供呼叫者重寫；
- 對於多執行緒，看不到執行緒資訊，或者看不到業務層 ID 的資訊。對於伺服器來說，有時候需要知道這個錯誤是哪個連線的，從而查詢這個連線之前的上下文資訊。

改進後的錯誤日誌變成了在底層返回，而不在底層列印在呼叫層列印，有呼叫鏈和堆疊，有執行緒切換的 ID 資訊，也有檔案的行數：

```
Error processing video, code=3001 : origin hub : codec parser : avc decoder
[100] video_avc_demux() at [srs_kernel_codec.cpp:676]
[100] on_video() at [srs_app_source.cpp:1076]
[101] on_video_imp() at [srs_app_source:2357]
```

> 從 Go2 的描述來說，實際上這個錯誤處理也還沒有考慮完備。從實際開發來說，已經比較實用了。

總結下 Go 的 error，錯誤處理應該注意以下幾點：

- 凡是有返回錯誤碼的函式，必須顯式的處理錯誤，如果要忽略錯誤，也應該顯式的忽略和寫註釋；
- 錯誤必須帶豐富的錯誤資訊，比如堆疊、發生錯誤時的引數、呼叫鏈給的描述等等。特別要強調變數，我看過太多日誌描述了一對常量，比如 "Verify the nonce, timestamp and token of specified appid failed"，而這個訊息一般會提到工單中，然後就是再問使用者，哪個 session 或 request 甚至時間點？這麼一大堆常量有啥用呢，關鍵是變數吶；
- 儘量避免重複的資訊，提高錯誤處理的開發體驗，糟糕的體驗會導致無效的錯誤處理程式碼，比如複製和漏掉關鍵資訊；
- 分離錯誤和日誌，發生錯誤時返回帶完整資訊的錯誤，在呼叫的頂層決定是將錯誤用日誌列印，還是傳送到監控系統，還是轉換錯誤，或者忽略。

<a name="39d99032" rel="nofollow"></a>
### Best Practice

推薦用 [github.com/pkg/errors](https://github.com/pkg/errors) 這個錯誤處理的庫，基本上是夠用的，參考 Refine: CopyFile，可以看到 CopyFile 中低階重複的程式碼已經比較少了：

```go
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
```

但是這個庫也有些小毛病：

1. `CopyFile` 中還是有可能會有重複的資訊，還是 Go2 的 `handle` 和 `check` 方案是最終解決；
1. 有時候需要使用者呼叫 `Wrap`，有時候是呼叫 `WithMessage`（不需要加堆疊時），這個真是非常不好用的地方(這個我們已經修改了庫，可以全部使用 Wrap 不用 WithMessage，會去掉重複的堆疊)。

<a name="Logger" rel="nofollow"></a>
## Logger

一直在碼程式碼，對日誌的理解總是不斷在變，大致分為幾個階段：

- 日誌是給人看的，是用來查問題的。出現問題後根據某些條件，去查不同程式或服務的日誌。日誌的關鍵是不能漏掉資訊，漏了關鍵日誌，可能就斷了關鍵的線索；

- 日誌必須要被關聯起來，上下文的日誌比單個日誌更重要。長連線需要根據會話關聯日誌；不同業務模型有不同的上下文，比如伺服器管理把伺服器作為關鍵資訊，查詢這個伺服器的相關日誌；全鏈路跨機器和服務的日誌跟蹤，需要定義可追蹤的邏輯 ID；

- 海量日誌是給機器看的，是結構化的，能主動報告問題，能從日誌中分析潛在的問題。日誌的關鍵是要被不同消費者消費，要輸出不同主題的日誌，不同的粒度的日誌。日誌可以用於排查問題，可以用於告警，可以用於分析業務情況。

> Note: 推薦閱讀 Kafka 對於 Log 的定義，廣義日誌是可以理解的訊息，[The Log: What every software engineer should know about real-time data's unifying abstraction](https://engineering.linkedin.com/distributed-systems/log-what-every-software-engineer-should-know-about-real-time-datas-unifying)。

### 完善資訊查問題

考慮一個服務，處理不同的連線請求：

```go
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)
}
```

這個日誌的主要問題，就是有了和沒有差不多，啥也看不出來，常量太多變數太少，缺失了太多的資訊。看起來這是個簡單問題，卻經常容易犯這種問題，需要我們在列印每個日誌時，需要思考這個日誌比較完善的資訊是什麼。上面程式輸出的日誌如下：

```bash
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
```

如果完善下上下文資訊，程式碼可以改成這樣：

```go
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))
}
```

輸出的日誌如下：

```bash
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 來作為上下文。

```go
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](#context) 的 WithValue 來將上下文相關的 ID 儲存，在列印日誌時將 ID 取出來；
- 如果有業務特徵，比如可以取 SessionID 的 hash 的前 8 個字元形成 ID，雖然容易碰撞，但是在一定範圍內不容易碰撞；
- 可以變成 json 格式的日誌，這樣可以將 level、id、tag、file、err 都變成可以程式分析的資料，送到 SLS 中處理；
- 對於切割和輪轉，推薦使用 [lumberjack](https://gopkg.in/natefinch/lumberjack.v2) 這個庫，程式的 logger 只要提供 `SetOutput(io.Writer)` 將日誌送給它處理就可以了。

> 當然，這要求函式傳參時需要帶 context.Context，一般在自己的應用程式中可以要求這麼做，凡是打日誌的地方要帶 context。對於庫，一般可以不打日誌，而返回帶堆疊的複雜錯誤的方式，參考 [Errors](#errors) 錯誤處理部分。

[點選下載《不一樣的 雙11 技術：阿里巴巴經濟體雲原生實踐》](https://developer.aliyun.com/article/728327?spm=a2c6h.12873581.0.dArticle728327.58dd3523BQjqaU&groupCode=alisoftwaretech)

[![ban.jpg](https://ucc.alicdn.com/pic/developer-ecology/1b80405560104b81964e323094da90eb.jpg)](https://developer.aliyun.com/article/728327?spm=a2c6h.12873581.0.dArticle728327.58dd3523BQjqaU&groupCode=alisoftwaretech)

**本書亮點**

- 雙11 超大規模 K8s 叢集實踐中，遇到的問題及解決方法詳述
- 雲原生化最佳組合：Kubernetes+容器+神龍，實現核心系統 100% 上雲的技術細節
- 雙 11 Service Mesh 超大規模落地解決方案

> “[阿里巴巴雲原生](https://developer.aliyun.com/group/alisoftwaretech/)關注微服務、Serverless、容器、Service Mesh 等技術領域、聚焦雲原生流行技術趨勢、雲原生大規模的落地實踐，做最懂雲原生開發者的技術圈。”

Go 開發關鍵技術指南 | Go 面向失敗程式設計 (內含超全知識大圖）

相關文章