Logging unhandled Golang panics

Question

I have a logrus log handler in my Golang application. Logs are formatted with JSONFormatter and are submitted as a single line to Datadog, which aggregates them and displays them nicely. However, I recently discovered a case where there's an unhandled panic, and this is not captured with the logrus logger. This results in the actual panic and stack trace being spread across multiple output lines, which Datadog collects individually. This costs us money and makes the logs very difficult to read.

I'm going to fix the issue, but in the event that any further unhandled panics happen, I'd like to be able to capture them using the logrus JSONFormatter.

Something like this:

package main

import (
    "os"
    "sync"

    "github.com/sirupsen/logrus"
)

var (
    loggerInstance *logrus.Entry
    once           sync.Once
    logger  = GetLogger()
)

// GetLogger initializes and returns a reference to a CustomLogger object.
func GetLogger() *logrus.Entry {
    once.Do(func() {
        logrus.SetFormatter(&logrus.JSONFormatter{})

        // We'll just pipe everything to stdout. It's json so Datadog will parse the level regardless
        logrus.SetOutput(os.Stdout)
        logrus.SetLevel(logrus.TraceLevel)                            // We'll leave this as trace and just filter out logs when we index them
        loggerInstance = logrus.WithFields(logrus.Fields{"env": "local"}) // Add env tag for easy log parsing
    })
    return loggerInstance
}

func main() {
    logger.Info("Logrus using json logging")
    logger.Warn("We are about to panic")

    var things = []string{
        "hi",
        "yes",
        "thing"}

    print("%s", things[len(things)])
}

This produces the following output. As you can see, the first two logs use logrus, but the unhandled panic does not.

{"env":"local","level":"info","msg":"Logrus using json logging","time":"2020-03-03T15:12:30-08:00"}
{"env":"local","level":"warning","msg":"We are about to panic","time":"2020-03-03T15:12:30-08:00"}
panic: runtime error: index out of range

goroutine 1 [running]:
main.main()
        /Users/nathan.deren/Library/Preferences/GoLand2019.3/scratches/scratch.go:38 +0xbe

Process finished with exit code 2

Is it possible to get those last several lines to log using logrus?

Answer 1

Try recover to catch all panics and log them. Without that, it'll write the panic msg to stderr:

func main() {
   defer func() {
        if r := recover(); r != nil {
            logger.Errorf("Panic: %v", r)
            os.Exit(1)
        }
    }()
    // rest of main here
}