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

時間 2020-01-15

標籤開發關鍵技術指南面向失敗編程內含知識简体版

原文原文鏈接

做者 | 楊成立（忘籬）阿里巴巴高級技術專家html

關注「阿里巴巴雲原生」公衆號，回覆 Go 便可查看清晰知識大圖！linux

導讀：從問題自己出發，不侷限於 Go 語言，探討服務器中經常遇到的問題，最後回到 Go 如何解決這些問題，爲你們提供 Go 開發的關鍵技術指南。咱們將以系列文章的形式推出《Go 開發的關鍵技術指南》，共有 4 篇文章，本文爲第 2 篇。

Could Not Recover

在 C/C++ 中，git

最苦惱的莫過於上線後發現有野指針或內存越界，致使不可能崩潰的地方崩潰；
最無語的是由於很早寫的日誌打印，好比 %s 把整數當字符串，忽然某天執行到了崩潰；
最無奈的是不管由於什麼崩潰都致使服務的全部用戶受到影響。

若是能有一種方案，將指針和內存都管理起來，避免用戶錯誤訪問和釋放，這樣雖然浪費了一部分的 CPU，可是能夠在快速變化的業務中避免這些頭疼的問題。在現代的高級語言中，好比 Java、Python 和 JS 的異常，以及 Go 的 panic-recover 都是這種機制。github

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

哪些能夠 Recover

Go 有 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，結果以下：json

$ 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。segmentfault

下面是 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 <- true
}

Recover 最佳實踐

通常 recover 後會判斷是否 err，有可能須要處理特殊的 error，通常也須要打印日誌或者告警，給一個 recover 的例子：

package main

import (
    "fmt"
)

type Handler interface {
    Filter(err error, r interface{}) error
}

type Logger interface {
    Ef(format string, a ...interface{})
}

// Handle panic by hdr, which filter the error.
// Finally log err with logger.
func HandlePanic(hdr Handler, logger Logger) error {
    return handlePanic(recover(), hdr, logger)
}

type hdrFunc func(err error, r interface{}) error

func (v hdrFunc) Filter(err error, r interface{}) error {
    return v(err, r)
}

type loggerFunc func(format string, a ...interface{})

func (v loggerFunc) Ef(format string, a ...interface{}) {
    v(format, a...)
}

// Handle panic by hdr, which filter the error.
// Finally log err with logger.
func HandlePanicFunc(hdr func(err error, r interface{}) error,
    logger func(format string, a ...interface{}),
) error {
    var f Handler
    if hdr != nil {
        f = hdrFunc(hdr)
    }

    var l Logger
    if logger != nil {
        l = loggerFunc(logger)
    }

    return handlePanic(recover(), f, l)
}

func handlePanic(r interface{}, hdr Handler, logger Logger) error {
    if r != nil {
        err, ok := r.(error)
        if !ok {
            err = fmt.Errorf("r is %v", r)
        }

        if hdr != nil {
            err = hdr.Filter(err, r)
        }

        if err != nil && logger != nil {
            logger.Ef("panic err %+v", err)
        }

        return err
    }

    return nil
}

func main() {
    func() {
        defer HandlePanicFunc(nil, func(format string, a ...interface{}) {
            fmt.Println(fmt.Sprintf(format, a...))
        })

        panic("ok")
    }()

    logger := func(format string, a ...interface{}) {
        fmt.Println(fmt.Sprintf(format, a...))
    }
    func() {
        defer HandlePanicFunc(nil, logger)

        panic("ok")
    }()
}

對於庫若是須要啓動 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 解決這個問題。

Map 競爭寫致使 panic 的實例代碼以下：

go
package main

import (
    "fmt"
    "time"
)

func main() {
    m := map[string]int{}
    p := func() {
        defer func() {
            if r := recover(); r != nil {
                fmt.Println(r)
            }
        }()
        for {
            m["t"] = 0
        }
    }

    go p()
    go p()
    time.Sleep(1 * time.Second)
}

注意：若是編譯時加了 -race，其餘競爭條件也會退出，通常用於死鎖檢測，但這會致使嚴重的性能問題，使用須要謹慎。

備註：通常標準庫中經過 throw 拋出的錯誤都是沒法 recover 的，搜索了下 Go1.11 一共有 690 個地方有調用 throw。

Go1.2 引入了能使用的最多線程數限制 ThreadLimit，若是超過了就 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 設置最大線程數。

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 <- true
      defer wg.Done()
      runtime.LockOSThread()
      time.Sleep(10 * time.Second)
      fmt.Println("Goroutine quit")
    }()

    <- c
    fmt.Println(fmt.Sprintf("Start goroutine #%v ok", i))
  }

  fmt.Println("Wait for all goroutines about 10s...")
  wg.Wait()

  fmt.Println("All goroutines done")
}

運行結果以下：

bash
Change max threads 10000=>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 <- true

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

      defer wg.Done()
      runtime.LockOSThread()
      time.Sleep(10 * time.Second)
      fmt.Println("Goroutine quit")
    }()

    <- c
    fmt.Println(fmt.Sprintf("Start goroutine #%v ok", i))
  }

  fmt.Println("Wait for all goroutines about 10s...")
  wg.Wait()

  fmt.Println("All goroutines done")
}

如何避免程序超過線程限制被幹掉？通常可能阻塞在 system call，那麼何時會阻塞？還有，GOMAXPROCS 又有什麼做用呢？

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》解釋得很清楚：

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》解釋很清楚，雖然設置了 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()
}

運行結果以下：

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 中的解釋:

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)？由於異常模型很難看出有沒有寫對，錯誤碼方式也不容易，相對會簡單點。
Go 的 error 有什麼問題，爲什麼 Go2 草案這麼大篇幅說 error 改進？由於 Go 雖然是錯誤碼但還不夠好，問題在於囉嗦、繁雜、缺失關鍵信息。
有哪些好用的 error 庫，如何和日誌配合使用？推薦用庫 pkg/errors；另外，避免日誌和錯誤混淆。
Go 的錯誤處理最佳實踐是什麼？配合日誌使用錯誤。錯誤須要帶上上下文、堆棧等信息。

錯誤和異常

咱們總會遇到非預期的非正常狀況，有一種是符合預期的，好比函數返回 error 並處理，這種叫作能夠預見到的錯誤，還有一種是預見不到的好比除零、空指針、數組越界等叫作 panic，panic 的處理主要參考 Defer, Panic, and Recover。

錯誤處理的模型通常有兩種，通常是錯誤碼模型好比 C/C++ 和 Go，還有異常模型好比 Java 和 C#。Go 沒有選擇異常模型，由於錯誤碼比異常更有優點，參考文章《Cleaner, more elegant, and wrong》以及《Cleaner, more elegant, and harder to recognize》。

看下面的代碼：

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

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

這段代碼的錯誤處理有不少問題，好比若是 CreateIndexes 拋出異常，會致使數據庫和表不會刪除，形成髒數據。從代碼編寫者和維護者的角度看這兩個模型，會比較清楚：

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

若是使用錯誤碼模型，很是容易就能看出錯誤處理沒有寫對，也能很容易知道作得好很差；要知道是否作得很是好，錯誤碼模型也不太容易。
若是使用異常模型，不管作的好很差都很難知道，並且也很難知道怎麼作好。

Errors in Go

Go 官方的 error 介紹，簡單一句話就是返回錯誤對象的方式，參考《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、Error Values和 Generics 泛型，兩個點都是錯誤處理的，這說明了 Go1 中對於錯誤是有改進的地方。

再詳細看下 Go2 的草案，錯誤處理：Error Handling 中，主要描述了發生錯誤時的重複代碼，以及不能便捷處理錯誤的狀況。好比草案中舉的這個例子 No Error Handling: CopyFile，沒有作任何錯誤處理：

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，錯誤處理是特別囉嗦，並且比較明顯有問題：

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，雖然囉嗦繁瑣不簡潔：

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，大體是引入關鍵字 handle 和 check，因爲本文重點側重 Go1 如何錯誤處理，就不展開分享了。

明顯上面每次都返回的 fmt.Errorf 信息也是不夠的，因此 Go2 還對於錯誤的值有提案，參考 Error Values。大規模程序應該面向錯誤編程和測試，同時錯誤應該包含足夠的信息。

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

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 標準庫擴展了 error，支持了 Unwrap、As 和 Is，但沒有支持堆棧信息。

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

從上面的例子能夠看出：

沒有堆棧信息，主要是想經過 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 甚至時間點？這麼一大堆常量有啥用呢，關鍵是變量吶；
儘可能避免重複的信息，提升錯誤處理的開發體驗，糟糕的體驗會致使無效的錯誤處理代碼，好比拷貝和漏掉關鍵信息；
分離錯誤和日誌，發生錯誤時返回帶完整信息的錯誤，在調用的頂層決定是將錯誤用日誌打印，仍是發送到監控系統，仍是轉換錯誤，或者忽略。

Best Practice

推薦用 github.com/pkg/errors 這個錯誤處理的庫，基本上是夠用的，參考 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

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

CopyFile 中仍是有可能會有重複的信息，仍是 Go2 的 handle 和 check 方案是最終解決；
有時候須要用戶調用 Wrap，有時候是調用 WithMessage（不須要加堆棧時），這個真是很是很差用的地方(這個咱們已經修改了庫，能夠所有使用 Wrap 不用 WithMessage，會去掉重複的堆棧)。

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) 將日誌送給它處理就能夠了。