[Go] How to output a stack trace safely on the gRPC server

When implementing a gRPC server in Go, most likely you’ll use google.golang.org/grpc.
If you implement it without being aware of it, the process will terminate when a panic occurs.

So how do you catch a panic without terminating the process?
And how do you output the stack trace of the panic?

In this article, I’ll introduce three point.

• How to output the stack trace of the panic
• How to keep the gRPC server process if a panic occurs
• How to output the stack trace of the panic on gRPC server

How to output the stack trace of the panic

First, let’s catch the panic and simply output an error.

package main

import (
    "fmt"
)

func main() {
    defer func() {
        if r := recover(); r != nil {
            fmt.Printf("%s\n", r)
        }
    }()

    var i *int
    fmt.Printf("i: %d\n", *i) // panic
}

The Go Playground

When you run this, the following log is outputted.

runtime error: invalid memory address or nil pointer dereference

This alone may be enough, but wait a minute.
It doesn’t tell which line in which file is causing the panic, isn’t it?
Now, let’s implement it so that it outputs a stack trace.
You can do by simply changing some of the above code.

package main
import (
    "fmt"
    "runtime/debug"
)
func main() {
    defer func() {
        if r := recover(); r != nil {
            fmt.Printf("%s\n\n%s\n", r, debug.Stack())
        }
    }()

    var i *int
    fmt.Printf("i: %d\n", *i) // panic
}

The Go Playground

When you run this, the following log is outputted.

runtime error: invalid memory address or nil pointer dereference

goroutine 1 [running]:
runtime/debug.Stack(0xc00006ad30, 0x4a9040, 0x560940)
	/usr/local/go-faketime/src/runtime/debug/stack.go:24 +0x9d
main.main.func1()
	/tmp/sandbox162480114/prog.go:16 +0x6e
panic(0x4a9040, 0x560940)
	/usr/local/go-faketime/src/runtime/panic.go:969 +0x166
main.main()
	/tmp/sandbox162480114/prog.go:21 +0x48

It’s important to output not only the stack trace, but the return value of recover().
Be sure to output both, as stack trace alone will not tell you what kind of panic has occurred.

How to keep the gRPC server process if a panic occurs

A simple implementation of the code to start the gRPC server would look like this.

package main

import (
    "net"
    "github.com/sirupsen/logrus"
    "google.golang.org/grpc"
    "google.golang.org/grpc/reflection"
)

func main() {
    listenPort, err := net.Listen("tcp", ":9090")
    if err != nil {
        logrus.Fatal(err)
    }

    server := grpc.NewServer()

    // Implement the `RegisterXxxServiceServer` here.

    reflection.Register(server)
    _ = server.Serve(listenPort)
    server.GracefulStop()
}

(If you auto-generate the gRPC server code from the proto file, the function with a name like RegisterXxxServiceServer should be implemented.)

If a panic occurs on a method on a server registered in RegisterXxxServiceServer, the process is terminated because it is not caught.
The reason for this is that the recover() function for catching a panic has not implemented.
You can catch a panic by simply changing some of the above code.

package main

import (
    "net"

    "github.com/sirupsen/logrus"
    "google.golang.org/grpc"
    "google.golang.org/grpc/reflection"
)

func main() {
    listenPort, err := net.Listen("tcp", ":9090")
    if err != nil {
        logrus.Fatal(err)
    }
    server := grpc.NewServer(
        grpc.UnaryInterceptor(
            grpc_recovery.UnaryServerInterceptor(),
        ),
    )

    // Implement the `RegisterXxxServiceServer` here.
 
    reflection.Register(server)
    _ = server.Serve(listenPort)
    server.GracefulStop()
}

I implemented for the grpc_recovery.UnaryServerInterceptor() applying.
What exactly does this interceptor do?
Let’s take a look at the implementation.

// UnaryServerInterceptor returns a new unary server interceptor for panic recovery.
func UnaryServerInterceptor(opts ...Option) grpc.UnaryServerInterceptor {
    o := evaluateOptions(opts)
    return func(ctx context.Context, req interface{}, info *grpc.UnaryServerInfo, handler grpc.UnaryHandler) (_ interface{}, err error) {
        defer func() {
            if r := recover(); r != nil {
                err = recoverFrom(ctx, r, o.recoveryHandlerFunc)
            }
        }()

        return handler(ctx, req)
    }
}

func recoverFrom(ctx context.Context, p interface{}, r RecoveryHandlerFuncContext) error {
    if r == nil {
        return status.Errorf(codes.Internal, "%s", p)
    }
    return r(ctx, p)
}

If nothing is passed as an argument to UnaryServerInterceptor, since o.recoveryHandlerFunc is nil, return status. Errorf(codes.Internal, "%s", p) will be executed.
Now, let’s implement it so that it outputs a stack trace.

How to output the stack trace of the panic on gRPC server

I pass the following function to grpc_recovery.UnaryServerInterceptor().
This function is executed when a panic is caught.

recoveryOpt := grpc_recovery.WithRecoveryHandlerContext(
    func(ctx context.Context, p interface{}) error {
        logrus.Errorf("[PANIC] %s\n\n%s", p, string(debug.Stack()))
        return status.Errorf(codes.Internal, "%s", p)
    },
)

This will output a stack trace.
In the case of nil pointer dereference, the following log will be outputted

[PANIC]: runtime error: invalid memory address or nil pointer dereference

goroutine 1 [running]:
runtime/debug.Stack(0xc00006ad30, 0x4a9040, 0x560940)
	/usr/local/go-faketime/src/runtime/debug/stack.go:24 +0x9d
main.main.func1()
	/tmp/sandbox162480114/prog.go:16 +0x6e
panic(0x4a9040, 0x560940)
	/usr/local/go-faketime/src/runtime/panic.go:969 +0x166
main.main()
	/tmp/sandbox162480114/prog.go:21 +0x48

In summary

In this time, I introduced to implement to output a stack track on gRPC server when a panic occurred.
At a minimum, you should implement recover() so that the process is not terminated, but if possible, you should also output a stack trace.
Let’s use gRPC in golang:)