Skip to content

Latest commit

 

History

History
935 lines (669 loc) · 34 KB

File metadata and controls

935 lines (669 loc) · 34 KB

九、Go 中的日志记录和并发测试

At this stage, you should be fairly comfortable with concurrency in Go and should be able to implement basic goroutines and concurrent mechanisms with ease.

我们还涉足了一些分布式并发模式,这些模式不仅通过应用本身进行管理,还通过第三方数据存储进行管理,用于在国会中并发运行的网络应用。

在本书的前面,我们研究了一些初步和基本的测试和日志记录。我们查看了 Go 内部测试工具的简单实现,使用 race 工具执行了一些竞争条件测试,并执行了一些基本的负载和性能测试。

然而,这里还有更多需要关注的地方,特别是当它涉及到并发代码的潜在黑洞时,我们已经看到在 goroutines 中运行的代码中出现了意外的行为,并且是非阻塞的。

在本章中,我们将进一步研究负载和性能测试,查看 Go 中的单元测试,并使用更高级的测试和调试进行实验。我们还将研究日志记录和报告的最佳实践,并进一步研究恐慌和恢复。

最后,我们想看看如何将所有这些东西不仅应用于我们的独立并发代码,还应用于分布式系统。

在此过程中,我们将介绍几种不同风格的单元测试框架。

Handling errors and logging

虽然我们没有特别提到它,但 Go 中错误处理的惯用性质使调试自然更容易。

对于 Go 代码中的任何大型函数来说,一个好的实践是返回一个错误作为许多较小方法和函数的返回值,这可能会带来负担,而且是不必要的。尽管如此,当我们在建造一个包含很多运动部件的东西时,这仍然是一个需要考虑的问题。

例如,考虑一个简单的函数:

func Add(x int, y int) int {
  return x + y
}

如果我们希望遵循“始终返回错误值”的一般规则,我们可能会尝试将此函数转换为以下代码:

package main
import
(
  "fmt"
  "errors"
  "reflect"
)

func Add(x int, y int) (int, error) {
  var err error

  xType := reflect.TypeOf(x).Kind()
  yType := reflect.TypeOf(y).Kind()
  if xType != reflect.Int || yType != reflect.Int {
    fmt.Println(xType)
    err = errors.New("Incorrect type for integer a or b!")
  }
  return x + y, err
}

func main() {

  sum,err := Add("foo",2)
  if err != nil {
    fmt.Println("Error",err)
  }
  fmt.Println(sum)
}

You can see that we're (very poorly) reinventing the wheel. Go's internal compiler kills this long before we ever see it. So, we should focus on things that the compiler may not catch and that can cause unexpected behavior in our applications, particularly when it comes to channels and listeners.

除非您希望自己处理异常,否则我们可以放手处理编译器将要处理的错误,而不会引起编译器特有的痛苦。如果没有真正的多态性,这通常会很麻烦,需要调用接口,如以下代码所示:

type Alpha struct {

}

type Numeric struct {

}

您可能还记得,创建接口和结构允许我们根据类型分别路由函数调用。这在以下代码中显示:

func (a Alpha) Add(x string, y string) (string, error) {
  var err error
  xType := reflect.TypeOf(x).Kind()
  yType := reflect.TypeOf(y).Kind()
  if xType != reflect.String || yType != reflect.String {
    err = errors.New("Incorrect type for strings a or b!")
  }
  finalString := x + y
  return finalString, err
}

func (n Numeric) Add(x int, y int) (int, error) {
  var err error

  xType := reflect.TypeOf(x).Kind()
  yType := reflect.TypeOf(y).Kind()
  if xType != reflect.Int || yType != reflect.Int {
    err = errors.New("Incorrect type for integer a or b!")
  }
  return x + y, err
}
func main() {
  n1 := Numeric{}
  a1 := Alpha{}
  z,err := n1.Add(5,2)	
  if err != nil {
    log.Println("Error",err)
  }
  log.Println(z)

  y,err := a1.Add("super","lative")
  if err != nil {
    log.Println("Error",err)
  }
  log.Println(y)
}

这仍然会报告编译器最终将捕获的内容,但也会处理编译器无法看到的某些形式的错误:外部输入。我们正在通过一个接口路由我们的Add()函数,该接口通过更明确地指导结构的参数和方法来提供一些额外的标准化。

例如,如果我们将用户输入作为值,并且需要计算该输入的类型,我们可能希望以这种方式报告错误,因为编译器永远不会知道我们的代码可以接受错误的类型。

发布 goroutine 日志

处理消息和日志的一种方法是将注意力集中在并发性和隔离上,即使用自己的日志程序将我们的 goroutine 束缚起来将所有内容与其他 goroutine 分开。

在这一点上,我们应该注意到,这可能无法扩展,也就是说,在某一点上,创建数千个或上万个具有自己的记录器的 goroutine 可能会变得非常昂贵,但在最小的规模下,这是完全可行和可管理的。

要单独进行此日志记录,我们需要将一个Logger实例绑定到每个 goroutine,如下代码所示:

package main

import
(
  "log"
  "os"
  "strconv"
)

const totalGoroutines = 5

type Worker struct {
  wLog *log.Logger
  Name string
}

具有讽刺意味的是,我们将创建一个泛型的Worker结构,它除了保留自己的Logger对象之外,不会做任何工作(至少在本例中不会)。代码如下:

func main() {
  done := make(chan bool)

  for i:=0; i< totalGoroutines; i++ {

    myWorker := Worker{}
    myWorker.Name = "Goroutine " + strconv.FormatInt(int64(i),10) + ""
    myWorker.wLog = log.New(os.Stderr, myWorker.Name, 1)
    go func(w *Worker) {

        w.wLog.Print("Hmm")

        done <- true
    }(&myWorker)
  }

每个goroutine 都有自己的日志例程到Worker。当我们将输出直接发送到控制台时,这在很大程度上是不必要的。但是,如果我们想将每个文件虹吸到它自己的日志文件中,我们可以使用以下代码:

  log.Println("...")

  <- done
}

使用 LiteIDE 进行更丰富、更容易的调试

In the earlier chapters of this book, we briefly addressed IDEs and gave a few examples of IDEs that have a tight integration with Go.

在我们检查日志记录和调试时,有一个 IDE 我们以前没有提到过,主要是因为它适用于一小部分语言,即 Go 和 Lua。然而,如果您最终主要或仅在 Go 中工作,您将发现它是绝对必要的,主要是因为它与调试、日志记录和反馈功能有关。

LiteIDE是跨平台的,在 OSX、Linux 和 Windows 上运行良好。它以 GUI 形式呈现的大量调试和测试好处是非常宝贵的,特别是如果您已经非常熟悉 Go 的话。最后一部分很重要,因为在使用简化编程过程的工具之前,开发人员通常从“艰苦学习”中获益最多。在展示漂亮的图标、菜单和弹出窗口之前,最好了解核心部分的工作方式和原因。话虽如此,LiteIDE 对于高级 Go 程序员来说是一个非常棒的免费工具。

通过将 Go 中的许多工具和错误报告形式化,我们可以通过在屏幕上看到它们来轻松完成一些更麻烦的调试任务。

LiteIDE also brings context awareness, code completion, go fmt, and more into our workspace. You can imagine how an IDE tuned specifically for Go can help you keep your code clean and bug free. Refer to the following screenshot:

Using the LiteIDE for richer and easier debugging

在 Windows 上显示输出和自动代码完成的 LiteIDE

Tip

Linux、OS X 和 Windows 的 LiteIDE 可在找到 https://code.google.com/p/liteide/

向屏幕发送错误

在本书中,我们通常通过向控制台发送消息来使用fmt.Println语法处理软错误、警告和一般消息。

虽然对于演示来说既快捷又简单,但使用log包处理这类事情可能是理想的选择。这是因为我们有更多的变通能力,因为log关系到我们希望我们的信息最终到达哪里。

就我们目前的目的而言,这些信息是空灵的。将一个简单的Println语句转换为Logger非常简单。

在使用以下代码行之前,我们一直在转发消息:

fmt.Println("Horrible error:",err)

您会注意到对Logger的更改非常相似:

myLogger.Println("Horrible error:", err)

这对于 goroutine 特别有用,因为我们可以创建一个全局Logger接口,该接口可以在任何地方访问,也可以将记录器的引用传递给各个 goroutine,并确保日志同时处理。

在整个应用中使用单个记录器的一个考虑因素是,为了分析的清晰性,我们可能需要单独记录各个进程。我们将在本章后面讨论更多关于这一点。

To replicate passing messages to the command line, we can simply use the following line of code:

log.Print("Message")

默认为stdout作为其io.writer-回想一下,我们可以将任何io.writer设置为日志的目的地。

但是,我们也希望能够快速、轻松地登录到文件。毕竟,任何在后台运行或作为守护进程运行的应用都需要一些更持久的东西。

将错误记录到文件

将错误发送到日志文件的方法有很多,在之后,我们可以通过内置的文件操作操作系统调用来处理这个。事实上,很多人都是这样做的。

然而,log包在命令行反馈和错误、警告和一般信息的永久存储之间提供了一些标准化和潜在的共生关系。

最简单的方法是使用os.OpenFile()方法(而不是os.Open()方法)打开一个文件,并将该引用作为io.Writer传递给我们的日志实例化。

让我们来看看下面例子中的这些功能:

package main

import (
  "log"
  "os"
)

func main() {
  logFile, _ := os.OpenFile("/var/www/test.log", os.O_RDWR, 0755)

  log.SetOutput(logFile)
  log.Println("Sending an entry to log!")

  logFile.Close()
}

在我们前面的goroutine 包中,我们可以将每个 goroutine 分配自己的文件,并将文件引用作为 io 编写器传递(我们需要具有对目标文件夹的写入权限)。代码如下:

  for i:=0; i< totalGoroutines; i++ {

    myWorker := Worker{}
    myWorker.Name = "Goroutine " + strconv.FormatInt(int64(i),10) 
      + ""
    myWorker.FileName = "/var/www/"+strconv.FormatInt(int64(i),10) 
      + ".log"
    tmpFile,_ :=   os.OpenFile(myWorker.FileName, os.O_CREATE, 
      0755)
    myWorker.File = tmpFile
    myWorker.wLog = log.New(myWorker.File, myWorker.Name, 1)
    go func(w *Worker) {

        w.wLog.Print("Hmm")

        done <- true
    }(&myWorker)
  }

将错误记录到内存中

当我们谈到将错误记录到内存时,我们实际上指的是数据存储,尽管除了波动性和有限的资源之外,肯定没有理由拒绝将日志记录到内存作为一种可行的选择。

在下一节中,我们将研究通过另一个包处理网络日志记录的更直接的方法,让我们描述一下并发分布式系统中的各种应用错误,而不需要太多麻烦。其思想是使用共享内存(如 Memcached 或共享内存数据存储)来传递日志消息。

虽然从技术上讲,这些仍然是日志文件(大多数数据存储将单个记录或文档保存为 JSON 编码的硬文件),但它与传统日志有着截然不同的感觉。

回到上一章中我们的老朋友 CouchDB,将日志消息传递到中央服务器几乎可以毫不费力地完成,而且它允许我们不仅跟踪单个机器,而且跟踪它们各自的并发 goroutine。代码如下:

package main

import
(
  "github.com/couchbaselabs/go-couchbase"
  "io"
  "time"
  "fmt"
  "os"
  "net/http"
  "crypto/md5"
  "encoding/hex"
)
type LogItem struct {
  ServerID string "json:server_id"
  Goroutine int "json:goroutine"
  Timestamp time.Time "json:time"
  Message string "json:message"
  Page string "json:page"
}

这将最终成为我们的 JSON 文档,并发送到我们的 Couchbase 服务器。我们将使用PageTimestampServerID作为组合散列键,以允许针对不同服务器对同一文档的多个并发请求分别记录,如下代码所示:

var currentGoroutine int

func (li LogItem) logRequest(bucket *couchbase.Bucket) {

  hash := md5.New()
  io.WriteString(hash,li.ServerID+li.Page+li.Timestamp.Format("Jan 
    1, 2014 12:00am"))
  hashString := hex.EncodeToString(hash.Sum(nil))
  bucket.Set(hashString,0,li)
  currentGoroutine = 0
}

当我们将currentGoroutine重置为0时,我们使用一个有意的竞争条件,允许 goroutine 在并发执行时通过数字 ID 报告自己。这使我们能够调试一个应用,该应用在调用某种形式的并发体系结构之前似乎工作正常。由于 goroutines 将通过 ID 进行自我识别,因此它允许我们添加更细粒度的消息路由。

通过 goroutineIDtimestampserverID指定不同的日志位置,可以快速从日志文件中提取出现的任何并发问题。这是使用以下代码完成的:

func main() {
  hostName, _ := os.Hostname()
  currentGoroutine = 0

  logClient, err := couchbase.Connect("http://localhost:8091/")
    if err != nil {
      fmt.Println("Error connecting to logging client", err)
    }
  logPool, err := logClient.GetPool("default")
    if err != nil {
      fmt.Println("Error getting pool",err)
    }
  logBucket, err := logPool.GetBucket("logs")
    if err != nil {
      fmt.Println("Error getting bucket",err)
    }
  http.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
    request := LogItem{}
    request.Goroutine = currentGoroutine
    request.ServerID = hostName
    request.Timestamp = time.Now()
    request.Message = "Request to " + r.URL.Path
    request.Page = r.URL.Path
    go request.logRequest(logBucket)

  })

  http.ListenAndServe(":8080",nil)

}

使用 log4go 包进行健壮的日志记录

与 Go 中的大部分内容一样,核心页面中有令人满意且可扩展的内容,可以通过第三方 Go 将其提升到一个新的层次。Go 的精彩日志记录包通过log4go真正实现了生命。

使用 log4go 大大简化了文件记录、控制台记录和通过 TCP/UDP 记录的过程。

提示

有关 log4go 的更多信息,请访问https://code.google.com/p/log4go/

log4go Logger接口的每个实例都可以通过 XML 配置文件进行配置,并且可以对其应用过滤器来指示消息传递的方向。让我们看一个简单的 HTTP 服务器,以展示如何将特定日志定向到位置,如以下代码所示:

package main

import (
  "code.google.com/p/log4go"
  "net/http"
  "fmt"
  "github.com/gorilla/mux"
)
var errorLog log4go.Logger
var errorLogWriter log4go.FileLogWriter

var accessLog log4go.Logger
var accessLogWriter *log4go.FileLogWriter

var screenLog log4go.Logger

var networkLog log4go.Logger

在前面的代码中,我们创建了四个不同的日志对象:一个将错误写入日志文件,一个将访问(页面请求)写入单独的文件,一个直接发送到控制台(用于重要通知),一个通过网络传递日志消息。

最后两个显然不需要FileLogWriter,但如果我们能够缓解并发访问的问题,则完全可以使用共享驱动器复制网络日志记录,如下代码所示:

func init() {
  fmt.Println("Web Server Starting")
}

func pageHandler(w http.ResponseWriter, r *http.Request) {
  pageFoundMessage := "Page found: " + r.URL.Path
  accessLog.Info(pageFoundMessage)
  networkLog.Info(pageFoundMessage)
  w.Write([]byte("Valid page"))
}

任何对有效页面的请求都会发送到此处,并将消息发送到web-access.log文件accessLog

func notFound(w http.ResponseWriter, r *http.Request) {
  pageNotFoundMessage := "Page not found / 404: " + r.URL.Path
  errorLog.Info(pageNotFoundMessage)
  w.Write([]byte("Page not found"))
}

accessLog文件一样,我们将接受任何404 / page not found请求,并将其直接路由到的notFound()方法,该方法将保存一条相当通用的错误消息以及请求的无效/缺失 URL。让我们看看在以下代码中如何处理极其重要的错误和消息:

func restricted(w http.ResponseWriter, r *http.Request) {
  message := "Restricted directory access attempt!"
  errorLog.Info(message)
  accessLog.Info(message)
  screenLog.Info(message)
  networkLog.Info(message)
  w.Write([]byte("Restricted!"))

}

restricted()功能和相应的screenLog表示一条我们认为关键的消息,不仅值得查看错误和访问日志,还可以作为networkLog项进行筛选和通过电线传递。换句话说,这是一个如此重要的信息,每个人都能理解。

在这个案例中,我们检测到有人试图进入我们的.git文件夹,这是一个相当常见的意外安全漏洞,众所周知,人们在自动上传和更新文件时会犯下该漏洞。由于我们在文件中表示明文密码,并且可能会将其暴露给外部世界,因此我们将根据请求捕获此密码,并将其传递给我们的关键和非关键日志机制。

我们还可以将其视为一个更开放的坏请求通知程序,值得网络开发人员立即关注。在以下代码中,我们将开始创建一些记录器:

func main() {

  screenLog = make(log4go.Logger)
  screenLog.AddFilter("stdout", log4go.DEBUG, log4go.NewConsoleLogWriter())

  errorLogWriter := log4go.NewFileLogWriter("web-errors.log", 
    false)
    errorLogWriter.SetFormat("%d %t - %M (%S)")
    errorLogWriter.SetRotate(false)
    errorLogWriter.SetRotateSize(0)
    errorLogWriter.SetRotateLines(0)
    errorLogWriter.SetRotateDaily(true)

由于 log4go 提供了一系列额外的日志选项,我们可以稍微了解一下日志的旋转和格式化方式,而不必专门用Sprintf或类似的东西来描述。

这里的选项既简单又富有表现力:

  • SetFormat:此允许我们指定各个日志行的外观。
  • SetRotate:此允许根据文件的大小和/或log中的行数自动旋转。SetRotateSize()选项设置消息中字节的旋转,SetRotateLines()设置lines的最大数量。SetRotateDaily()功能允许我们基于日期创建新的日志文件,而不考虑之前功能中的设置。这是一种相当常见的日志记录技术,通常手工编写代码会很麻烦。

日志格式的输出结果如下所示:

04/13/14 10:46 - Page found%!(EXTRA string=/valid) (main.pageHandler:24)

%S部分是源代码,它为我们调用日志的应用部分提供了行号和方法跟踪:

  errorLog = make(log4go.Logger)
  errorLog.AddFilter("file", log4go.DEBUG, errorLogWriter)

  networkLog = make(log4go.Logger)
  networkLog.AddFilter("network", log4go.DEBUG, log4go.NewSocketLogWriter("tcp", "localhost:3000"))

我们的网络日志通过 TCP 将 JSON 编码的消息发送到我们提供的地址。在下一节代码中,我们将展示一个非常简单的处理服务器,它将日志消息转换为一个集中的日志文件:

  accessLogWriter = log4go.NewFileLogWriter("web-access.log",false)
    accessLogWriter.SetFormat("%d %t - %M (%S)")
    accessLogWriter.SetRotate(true)
    accessLogWriter.SetRotateSize(0)
    accessLogWriter.SetRotateLines(500)
    accessLogWriter.SetRotateDaily(false)

我们的accessLogWritererrorLogWriter类似,只是我们不是每天旋转,而是每 500 行旋转一次。这里的想法是,访问日志当然会比错误日志更频繁地被触及。代码如下:

  accessLog = make(log4go.Logger)
  accessLog.AddFilter("file",log4go.DEBUG,accessLogWriter)

  rtr := mux.NewRouter()
  rtr.HandleFunc("/valid", pageHandler)
  rtr.HandleFunc("/.git/", restricted)
  rtr.NotFoundHandler = http.HandlerFunc(notFound)

在前面的代码中,我们使用 Gorilla Mux 包进行路由。这使我们更容易访问404处理程序,在直接内置到 Go 中的基本http包中修改该处理程序并不简单。代码如下:

  http.Handle("/", rtr)
  http.ListenAndServe(":8080", nil)
}

像这样构建网络日志系统的接收端在 Go 中也非常简单,因为我们只构建了另一个 TCP 客户端,它可以处理 JSON 编码的消息。

我们可以使用一个接收服务器来实现这一点,该服务器看起来与前面章节中的 TCP 聊天服务器非常相似。代码如下:

package main

import
(
  "net"
  "fmt"
)

type Connection struct {

}

func (c Connection) Listen(l net.Listener) {
  for {
    conn,_ := l.Accept()
    go c.logListen(conn)
  }
}

与聊天服务器一样,我们将侦听器绑定到一个Connection结构,如下代码所示:

func (c *Connection) logListen(conn net.Conn) {
  for {
    buf := make([]byte, 1024)
    n, _ := conn.Read(buf)
    fmt.Println("Log Message",string(n))
  }
}

在前面的代码中,我们通过 JSON 接收日志消息。在这一点上,我们并没有拆封 JSON,但在前面的一章中我们已经展示了如何做到这一点。

由于这个原因,发送的任何消息都将被推送到缓冲区中,根据信息的详细程度扩展缓冲区的大小可能是有意义的。

func main() {
  serverClosed := make(chan bool)

  listener, err := net.Listen("tcp", ":3000")
  if err != nil {
    fmt.Println ("Could not start server!",err)
  }

  Conn := Connection{}

  go Conn.Listen(listener)

  <-serverClosed
}

您可以想象网络日志记录是如何有用的,尤其是在服务器集群中,您可能有一个选择,例如 web 服务器,并且您不想将单个日志文件协调到单个日志中。

Panicking

对于所有捕获错误和记录它们的讨论,我们认为 T3 可能应该考虑 GO 的 T0 和 T1。

正如前面简要讨论的,与try/catch/finally甚至 Go 的内置错误返回值约定相比,panic()recover()是一种更基本、更直接、更明确的错误检测方法。按照设计,panic()展开堆栈并导致程序退出,除非调用recover()。这意味着除非显式恢复,否则应用将结束。

那么,除了停止执行之外,这还有什么用处呢?毕竟,我们可以捕获错误并通过类似于以下代码的方式手动结束应用:

package main

import
(
  "fmt"
  "os"
)

func processNumber(un int) {

  if un < 1 || un > 4 {
    fmt.Println("Now you've done it!")
    os.Exit(1)
  }else {
    fmt.Println("Good, you can read simple instructions.")
  }
}

func main() {
  userNum := 0
  fmt.Println("Enter a number between 1 and 4.")
  _,err := fmt.Scanf("%d",&userNum)
    if err != nil {}

  processNumber(userNum)
}

然而,虽然此功能进行健全性检查并设定永久、不可逆的应用退出,panic()recover()允许我们反映特定包和/或方法中的错误,保存这些错误,然后优雅地恢复。

当我们处理从其他方法调用的其他方法调用的方法时,这非常有用。很难识别特定错误的深度嵌入或递归函数类型是panic()recover()最为有利的。您还可以想象此功能与日志记录的配合效果如何。

恢复

panic()函数本身相当简单,与recover()defer()搭配使用时,它确实变得非常有用。

以为例,一个应用从命令行返回关于文件的元信息。应用的主要部分将侦听用户输入,将其传递到将打开文件的函数中,然后将该文件引用传递给另一个将获取文件详细信息的函数。

现在,我们显然可以在整个过程中将错误堆叠为返回元素,或者我们可以在过程中惊慌失措,恢复步骤,并在底部收集错误,以便直接记录和/或向控制台报告。

与前一种方法相比,避免使用意大利面代码是一种受欢迎的副作用。从一般意义上考虑这一点(这是伪代码):

func getFileDetails(fileName string) error {
  return err
}

func openFile(fileName string) error {
  details,err := getFileDetails(fileName)
  return err
}

func main() {

  file,err := openFile(fileName)

}

只要出现一个错误,就完全可以用这种方式处理我们的应用。但是,当每个单独的函数都有一个或多个故障点时,我们将需要越来越多的返回值,以及一种将所有返回值协调为一条或多条整体错误消息的方法。检查以下代码:

package main

import
(
  "os"
  "fmt"
  "strconv"
)

func gatherPanics() {
  if rec := recover(); rec != nil {
    fmt.Println("Critical Error:", rec)
  }
}

这是我们的通用恢复函数,它在我们希望捕获任何恐慌的每个方法之前调用。让我们看一个函数来推断文件的详细信息:

func getFileDetails(fileName string) {
  defer gatherPanics()
  finfo,err := os.Stat(fileName)
  if err != nil {
    panic("Cannot access file")
  }else {
    fmt.Println("Size: ", strconv.FormatInt(finfo.Size(),10))
  }
}

func openFile(fileName string) {
  defer gatherPanics()
  if _, err := os.Stat(fileName); err != nil {
    panic("File does not exist")
  }

}

上述代码中的两个函数只是试图打开一个文件,如果该文件不存在,则会死机。第二个方法getFileDetails()是从main()函数调用的,因此无论openFile()中是否存在阻塞错误,它都将始终执行。

在真实的世界中,我们通常会开发这样的应用:非致命错误只会使应用的一部分停止工作,但不会导致整个应用崩溃。检查以下代码:

func main() {
  var fileName string
  fmt.Print("Enter filename>")
  _,err := fmt.Scanf("%s",&fileName)
  if err != nil {}
  fmt.Println("Getting info for",fileName)

  openFile(fileName)
  getFileDetails(fileName)

}

如果我们要从gatherPanics()方法中删除recover()代码,那么当文件不存在时,应用就会崩溃。

这似乎很理想,但想象一下这样一个场景:用户为一个他们没有查看权限的目录选择一个不存在的文件。当他们解决第一个问题时,他们将看到第二个问题,而不是一次看到所有潜在的问题。

The value of expressive errors can't be overstated from a user experience standpoint. Gathering and presenting expressive errors is made easier through this methodology—even a try/catch/finally requires that we (as developers) explicitly do something with the returned error in the catch clause.

记录我们的恐慌

在前面的代码中,除了捕捉恐慌之外,我们还可以非常简单地集成日志机制。

关于日志记录,我们没有讨论的一个问题是何时进行日志记录的概念。正如我们前面的示例所示,我们有时会遇到应该记录的问题,但可以通过未来的用户操作来缓解。因此,我们可以选择立即记录错误,或将其保存到执行结束或更大的函数。

立即记录日志的主要好处是,我们不会受到实际崩溃的影响,从而无法保存日志。以以下为例:

type LogItem struct {
  Message string
  Function string
}

var Logs []LogItem

我们使用以下代码创建了一个日志struct和一个LogItems切片:

func SaveLogs() {
  logFile := log4go.NewFileLogWriter("errors.log",false)
    logFile.SetFormat("%d %t - %M (%S)")
    logFile.SetRotate(true)
    logFile.SetRotateSize(0)
    logFile.SetRotateLines(500)
    logFile.SetRotateDaily(false)

  errorLog := make(log4go.Logger)
  errorLog.AddFilter("file",log4go.DEBUG,logFile)
  for i:= range Logs {
    errorLog.Info(Logs[i].Message + " in " + Logs[i].Function)
  }

}

从表面上看,这就是我们捕获的所有LogItems将被转换为日志文件中行项目的良好集合的地方。但是,如以下代码所示,存在一个问题:

func registerError(block chan bool) {

  Log := LogItem{ Message:"An Error Has Occurred!", Function: "registerError()"}
  Logs = append(Logs,Log)
  block <- true
}

在 goroutine 中执行,此函数是非阻塞的,允许主线程继续执行。问题在于在 goroutine 之后运行的以下代码导致我们根本不记录任何日志:

func separateFunction() {
  panic("Application quitting!")
}

无论是手动调用还是由二进制本身调用,过早退出的应用都会阻止我们编写日志文件,因为该方法会推迟到main()方法结束。代码如下:

func main() {
  block := make(chan bool)
  defer SaveLogs()
  go func(block chan bool) {

    registerError(block)

  }(block)

  separateFunction()

}

然而,这里的权衡是性能。如果我们每次想记录一些东西时都执行一个文件操作,那么我们就有可能在应用中引入一个瓶颈。在前面的代码中,错误是通过 goroutine 发送的,但是是以阻塞代码的形式写入的。如果我们将日志写入直接引入registerError(),它会减慢我们最终的应用。

如前所述,缓解这些问题并允许应用仍保存所有日志条目的一个机会是利用内存日志记录或网络日志记录。

使用并发代码捕获堆栈跟踪

在早期的 Go 版本中,能够正确地执行来自我们的源的堆栈跟踪是一项艰巨的任务,这是用户早期对 Go 中一般错误处理的许多抱怨和担忧的象征。

While the Go team has remained vigilant about the right way to do this (as they have with several other key language features such as a lack of generics), stack traces and stack info have been tweaked a bit as the language has grown.

Using the runtime package for granular stack traces

为了直接捕获堆栈跟踪,我们可以从内置的运行时包中收集一些有用的信息。

具体来说,Go 提供了一些工具,让我们能够深入了解 goroutine 的调用和/或断点。以下是运行时包中的函数:

  • runtime.Caller():返回 goroutine 的父函数信息
  • runtime.Stack():为堆栈跟踪中的数据量分配一个缓冲区,然后用跟踪填充该缓冲区
  • runtime.NumGoroutine():返回打开的 goroutine 总数

我们可以利用前面的三个工具来更好地描述任何给定 goroutine 和相关错误的内部工作。

使用以下代码,我们将生成一些执行随机操作的随机 goroutine,并不仅记录 goroutine 的日志消息,还记录堆栈跟踪和 goroutine 的调用方:

package main

import
(
  "os"
  "fmt"
  "runtime"
  "strconv"
  "code.google.com/p/log4go"
)

type LogItem struct {
  Message string
}

var LogItems []LogItem

func saveLogs() {
  logFile := log4go.NewFileLogWriter("stack.log", false)
    logFile.SetFormat("%d %t - %M (%S)")
    logFile.SetRotate(false)
    logFile.SetRotateSize(0)
    logFile.SetRotateLines(0)
    logFile.SetRotateDaily(true)

  logStack := make(log4go.Logger)
  logStack.AddFilter("file", log4go.DEBUG, logFile)
  for i := range LogItems {
    fmt.Println(LogItems[i].Message)
    logStack.Info(LogItems[i].Message)
  }
}

saveLogs()函数仅获取LogItems的映射,并根据log4go 将其应用于文件,正如我们在本章前面所做的那样。接下来,我们来看看函数,它提供了关于我们 goroutines 的详细信息:

func goDetails(done chan bool) {
  i := 0
  for {
    var message string
    stackBuf := make([]byte,1024)
    stack := runtime.Stack(stackBuf, false)
    stack++
    _, callerFile, callerLine, ok := runtime.Caller(0)
    message = "Goroutine from " + string(callerLine) + "" + 
      string(callerFile) + " stack:" + 	string(stackBuf)
    openGoroutines := runtime.NumGoroutine()

    if (ok == true) {
      message = message + callerFile
    }

    message = message + strconv.FormatInt(int64(openGoroutines),10) + " goroutines 
        active"

    li := LogItem{ Message: message}

    LogItems = append(LogItems,li)
    if i == 20 {
      done <- true
      break
    }

    i++
  }
}

这是我们收集关于 goroutine 的更多细节的地方。runtime.Caller()函数提供了几个返回值:它的指针、调用者的文件名、调用者的行。最后一个返回值指示是否可以找到调用方。

As mentioned previously, runtime.NumGoroutine() gives us the number of extant goroutines that have not yet been closed.

然后,在runtime.Stack(stackBuf, false)中,我们用堆栈跟踪填充缓冲区。请注意,我们并没有将这个字节数组修剪到长度。

这三个都被传递到LogItem.Message中供以后使用。让我们看看main()函数中的设置:

func main() {
  done := make(chan bool)

  go goDetails(done)
  for i:= 0; i < 10; i++ {
    go goDetails(done)
  }

  for {
    select {
      case d := <-done:
        if d == true {
          saveLogs()
          os.Exit(1)
        }
    }
  }

}

最后,我们通过一些本身正在执行循环的 goroutine 进行循环,并在完成后退出。

当我们检查日志文件时,我们得到了比以前多得多的关于 goroutine 的详细信息,如下代码所示:

04/16/14 23:25 - Goroutine from + /var/log/go/ch9_11_stacktrace.goch9_11_stacktrace.go stack:goroutine 4 [running]:
main.goDetails(0xc08400b300)
  /var/log/go/ch9_11_stacktrace.goch9_11_stacktrace.go:41 +0x8e
created by main.main
  /var/log/go/ch9_11_stacktrace.goch9_11_stacktrace.go:69 +0x4c

  /var/log/go/ch9_11_stacktrace.goch9_11_stacktrace.go14 goroutines active (main.saveLogs:31)

提示

有关运行时包的更多信息,请转到http://golang.org/pkg/runtime/

总结

调试、测试和记录并发代码可能特别麻烦,通常是当并发 goroutine 以一种看似无声的方式失败或无法执行时。

我们研究了各种日志记录方法,从文件到控制台到内存再到网络日志记录,并研究了并发应用块如何适应这些不同的实现。

到目前为止,您应该能够轻松自然地创建健壮且富有表现力的日志,这些日志可以自动循环,不会造成延迟或瓶颈,并有助于调试应用。

您应该熟悉运行时包的基本知识。我们将深入研究测试包,更明确地控制 goroutine,并在下一章深入挖掘时进行单元测试。

除了进一步检查测试和运行时包外,在最后一章中,我们还将讨论 Go 中更高级的并发主题,并回顾一些与 Go 语言编程相关的总体最佳实践。