Golang 捕获意外丢失的 Panic 日志

前言

你是否曾经遇到过 Golang 应用意外重启但没有任何错误日志停留，怀疑出现 panic 但是苦于没有证据？那么今天就来解决一下可能出现的一个问题，捕获哪些可能被我遗漏的 panic 日志。

原因

首先我们要清楚一下出现这样情况的可能原因是什么。(之所以我说可能的原因，是因为不是所有没有日志的情况都是这个原因) 。对于日志的处理方式，通常我们会使用一些日志框架帮助我们进行处理，特别是对于文件，将日志打印到文件中的情况。而当一个 panic 出现的时候，如果我们没有捕获它，它的错误信息只会被打印到 stderr 中去，也就是标准错误输出。

所以，对于一些容器化部署的项目来说，特别是部署到 k8s 上的时候，会统一使用 std 作为日志捕获和处理的手段，无论是采用 sidecar 还是其他方式采集，将 std 的输出直接采集发送到日志系统，所有日志系统进行归档统一处理就一般没啥问题。而对于一些仅使用二进制或者是 docker 部署的情况，又或是没有采用日志采集 std 的时候就可能会出现了。

实验

这里我使用 zap 作为日志组件引入，如果你不熟悉可以直接忽略这部分的代码。然后快速实验一下，对于日志文件是否有 panic 记录。

package main

import (
    "fmt"
    rotatelogs "github.com/lestrrat-go/file-rotatelogs"
    "go.uber.org/zap"
    "go.uber.org/zap/zapcore"
    "os"
    "runtime"
    "syscall"
    "time"
)

func main() {
    logger := initLogger()
    logger.Debug("debug")
    logger.Info("info")
    logger.Warn("warn")
    logger.Error("error")

    go func() {
        panic("exit")
    }()

    time.Sleep(time.Second * 3)
}

func initLogger() *zap.Logger {
    errWriter, err := rotatelogs.New(
        "linkinstar_err_%Y-%m-%d.log",
    )
    if err != nil {
        panic(err)
    }

    consoleDebugging := zapcore.Lock(os.Stdout)
    consoleEncoderConfig := zap.NewDevelopmentEncoderConfig()
    consoleEncoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder
    consoleEncoderConfig.EncodeLevel = zapcore.CapitalColorLevelEncoder
    consoleEncoder := zapcore.NewConsoleEncoder(consoleEncoderConfig)
    consoleCore := zapcore.NewCore(consoleEncoder, consoleDebugging, zapcore.DebugLevel)

    errorCore := zapcore.AddSync(errWriter)
    fileEncodeConfig := zap.NewProductionEncoderConfig()
    fileEncodeConfig.EncodeTime = zapcore.ISO8601TimeEncoder
    fileEncoder := zapcore.NewConsoleEncoder(fileEncodeConfig)
    lowPriority := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool {
        return lvl >= zapcore.DebugLevel
    })

    core := zapcore.NewTee(consoleCore, zapcore.NewCore(fileEncoder, errorCore, lowPriority))
    caller := zap.AddCaller()
    logger := zap.New(core, caller, zap.Development())
    zap.ReplaceGlobals(logger)
    return logger
}

可以看到日志文件里面输出的是：

2024-12-10T15:56:15.505+0800	debug	main.go:15	debug
2024-12-10T15:56:15.506+0800	info	main.go:16	info
2024-12-10T15:56:15.506+0800	warn	main.go:17	warn
2024-12-10T15:56:15.506+0800	error	main.go:18	error

并没有 panic 日志。而在实际项目中，如果有第三方的依赖意外导致了 panic 那么就很有可能是这样的情况，容器重启，但没有任何现场日志保留。

解决方案

说起来很简单，也是网上来的方案，非常行之有效，就是将 stderr 重写到你需要的文件里面。即下面的 RewriteStderrFile

package main

import (
    "fmt"
    rotatelogs "github.com/lestrrat-go/file-rotatelogs"
    "go.uber.org/zap"
    "go.uber.org/zap/zapcore"
    "log"
    "os"
    "runtime"
    "syscall"
    "time"
)

func main() {
    RewriteStderrFile("linkinstar_panic.log")

    logger := initLogger()
    logger.Debug("debug")
    logger.Info("info")
    logger.Warn("warn")
    logger.Error("error")

    log.Println("print to std")
    fmt.Fprintf(os.Stderr, "print to stderr\n")

    go func() {
        panic("exit")
    }()

    time.Sleep(time.Second * 3)
}

func initLogger() *zap.Logger {
    errWriter, err := rotatelogs.New(
        "linkinstar_err_%Y-%m-%d.log",
    )
    if err != nil {
        panic(err)
    }

    consoleDebugging := zapcore.Lock(os.Stdout)
    consoleEncoderConfig := zap.NewDevelopmentEncoderConfig()
    consoleEncoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder
    consoleEncoderConfig.EncodeLevel = zapcore.CapitalColorLevelEncoder
    consoleEncoder := zapcore.NewConsoleEncoder(consoleEncoderConfig)
    consoleCore := zapcore.NewCore(consoleEncoder, consoleDebugging, zapcore.DebugLevel)

    errorCore := zapcore.AddSync(errWriter)
    fileEncodeConfig := zap.NewProductionEncoderConfig()
    fileEncodeConfig.EncodeTime = zapcore.ISO8601TimeEncoder
    fileEncoder := zapcore.NewConsoleEncoder(fileEncodeConfig)
    lowPriority := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool {
        return lvl >= zapcore.DebugLevel
    })

    core := zapcore.NewTee(consoleCore, zapcore.NewCore(fileEncoder, errorCore, lowPriority))
    caller := zap.AddCaller()
    logger := zap.New(core, caller, zap.Development())
    zap.ReplaceGlobals(logger)
    return logger
}

// 从此处开始为解决方案
var stdErrFileHandler *os.File

func RewriteStderrFile(panicFilePath string) error {
    if runtime.GOOS == "windows" {
        return nil
    }

    file, err := os.OpenFile(panicFilePath, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0666)
    if err != nil {
        fmt.Println(err)
        return err
    }
    stdErrFileHandler = file
    if err = syscall.Dup2(int(file.Fd()), int(os.Stderr.Fd())); err != nil {
        fmt.Println(err)
        return err
    }
    runtime.SetFinalizer(stdErrFileHandler, func(fd *os.File) {
        fd.Close()
    })
    return nil
}

这样我们就会额外得到一个 panic.log

2024/12/10 16:01:03 print to std
print to stderr
panic: exit

goroutine 35 [running]:
main.main.func1()
	xxx/main.go:28 +0x2c
created by main.main in goroutine 1
	xxx/main.go:27 +0x138