search

cloudnative-pg / cnpg-i-machinery

CloudNativePG Interface Machinery
Apache License 2.0
2 stars 3 forks source link

feat: log server errors #54

Closed leonardoce closed 1 month ago

leonardoce commented 1 month ago

This patch adds couple of interceptors to log errors raised by the service implementations. These are useful to get the panic stack trace, too.

Closes: #33

leonardoce commented 1 month ago

With this patch, the following log entry is emitted when an implementation is raising an error:

{
  "level": "error",
  "ts": 1723124610.3397481,
  "caller": "pluginhelper/grpc.go:55",
  "msg": "Error while handling GRPC request",
  "info": {
    "Server": {},
    "FullMethod": "/cnpgi.operator_lifecycle.v1.OperatorLifecycle/LifecycleHook"
  },
  "error": "panic caught: this is a panic\n\ngoroutine 79 [running]:\ngithub.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/recovery.recoverFrom({0x1c805a0?, 0xc0001975c0?}, {0x1708580, 0x1c62f60}, 0xc00014354f?)\n\t/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware/v2@v2.1.0/interceptors/recovery/interceptors.go:57 +0x65\ngithub.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/recovery.UnaryServerInterceptor.func1.1()\n\t/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware/v2@v2.1.0/interceptors/recovery/interceptors.go:30 +0x67\npanic({0x1708580?, 0x1c62f60?})\n\t/usr/local/go/src/runtime/panic.go:770 +0x132\ngithub.com/cloudnative-pg/cnpg-i-hello-world/internal/lifecycle.Implementation.reconcileMetadata(...)\n\t/app/internal/lifecycle/lifecycle.go:78\ngithub.com/cloudnative-pg/cnpg-i-hello-world/internal/lifecycle.Implementation.LifecycleHook({{}}, {0xc000211f80?, 0xc000143708?}, 0xc000697680)\n\t/app/internal/lifecycle/lifecycle.go:65 +0x91\ngithub.com/cloudnative-pg/cnpg-i/pkg/lifecycle._OperatorLifecycle_LifecycleHook_Handler.func1({0x1c805a0?, 0xc0001975c0?}, {0x18909e0?, 0xc000697680?})\n\t/go/pkg/mod/github.com/cloudnative-pg/cnpg-i@v0.0.0-20240806095732-9ea12e76a6ee/pkg/lifecycle/operator_lifecycle_grpc.pb.go:129 +0xcb\ngithub.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/recovery.UnaryServerInterceptor.func1({0x1c805a0?, 0xc0001975c0?}, {0x18909e0?, 0xc000697680?}, 0x17af740?, 0x29d7840?)\n\t/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware/v2@v2.1.0/interceptors/recovery/interceptors.go:34 +0x9c\ngoogle.golang.org/grpc.getChainUnaryHandler.func1({0x1c805a0, 0xc0001975c0}, {0x18909e0, 0xc000697680})\n\t/go/pkg/mod/google.golang.org/grpc@v1.65.0/server.go:1196 +0xb2\ngithub.com/cloudnative-pg/cnpg-i-machinery/pkg/pluginhelper.run.loggingUnaryServerInterceptor.func2({0x1c805a0?, 0xc000197560?}, {0x18909e0, 0xc000697680}, 0xc00028e7e0?, 0xc000210080)\n\t/go/pkg/mod/github.com/leonardoce/cnpg-i-machinery@v0.0.0-20240808133655-263e48aced5e/pkg/pluginhelper/grpc.go:39 +0x53\ngoogle.golang.org/grpc.getChainUnaryHandler.func1({0x1c805a0, 0xc000197560}, {0x18909e0, 0xc000697680})\n\t/go/pkg/mod/google.golang.org/grpc@v1.65.0/server.go:1196 +0xb2\ngithub.com/cloudnative-pg/cnpg-i-machinery/pkg/pluginhelper.run.logFailedRequestsUnaryServerInterceptor.func1({0x1c805a0?, 0xc000197560?}, {0x18909e0?, 0xc000697680?}, 0xc00028e7e0, 0xc000010420?)\n\t/go/pkg/mod/github.com/leonardoce/cnpg-i-machinery@v0.0.0-20240808133655-263e48aced5e/pkg/pluginhelper/grpc.go:53 +0x69\ngoogle.golang.org/grpc.NewServer.chainUnaryServerInterceptors.chainUnaryInterceptors.func1({0x1c805a0, 0xc000197560}, {0x18909e0, 0xc000697680}, 0xc00028e7e0, 0x80?)\n\t/go/pkg/mod/google.golang.org/grpc@v1.65.0/server.go:1187 +0x85\ngithub.com/cloudnative-pg/cnpg-i/pkg/lifecycle._OperatorLifecycle_LifecycleHook_Handler({0x186c960, 0x29d7840}, {0x1c805a0, 0xc000197560}, 0xc0005cad00, 0xc0000a4440)\n\t/go/pkg/mod/github.com/cloudnative-pg/cnpg-i@v0.0.0-20240806095732-9ea12e76a6ee/pkg/lifecycle/operator_lifecycle_grpc.pb.go:131 +0x143\ngoogle.golang.org/grpc.(*Server).processUnaryRPC(0xc00022cc00, {0x1c805a0, 0xc0001974d0}, {0x1c87880, 0xc0005f4000}, 0xc0005f0240, 0xc0000b5110, 0x2951b38, 0x0)\n\t/go/pkg/mod/google.golang.org/grpc@v1.65.0/server.go:1379 +0xdf8\ngoogle.golang.org/grpc.(*Server).handleStream(0xc00022cc00, {0x1c87880, 0xc0005f4000}, 0xc0005f0240)\n\t/go/pkg/mod/google.golang.org/grpc@v1.65.0/server.go:1790 +0xe8b\ngoogle.golang.org/grpc.(*Server).serveStreams.func2.1()\n\t/go/pkg/mod/google.golang.org/grpc@v1.65.0/server.go:1029 +0x8b\ncreated by google.golang.org/grpc.(*Server).serveStreams.func2 in goroutine 64\n\t/go/pkg/mod/google.golang.org/grpc@v1.65.0/server.go:1040 +0x125\n",
  "stacktrace": "github.com/cloudnative-pg/cnpg-i-machinery/pkg/pluginhelper.run.logFailedRequestsUnaryServerInterceptor.func1\n\t/go/pkg/mod/github.com/leonardoce/cnpg-i-machinery@v0.0.0-20240808133655-263e48aced5e/pkg/pluginhelper/grpc.go:55\ngoogle.golang.org/grpc.NewServer.chainUnaryServerInterceptors.chainUnaryInterceptors.func1\n\t/go/pkg/mod/google.golang.org/grpc@v1.65.0/server.go:1187\ngithub.com/cloudnative-pg/cnpg-i/pkg/lifecycle._OperatorLifecycle_LifecycleHook_Handler\n\t/go/pkg/mod/github.com/cloudnative-pg/cnpg-i@v0.0.0-20240806095732-9ea12e76a6ee/pkg/lifecycle/operator_lifecycle_grpc.pb.go:131\ngoogle.golang.org/grpc.(*Server).processUnaryRPC\n\t/go/pkg/mod/google.golang.org/grpc@v1.65.0/server.go:1379\ngoogle.golang.org/grpc.(*Server).handleStream\n\t/go/pkg/mod/google.golang.org/grpc@v1.65.0/server.go:1790\ngoogle.golang.org/grpc.(*Server).serveStreams.func2.1\n\t/go/pkg/mod/google.golang.org/grpc@v1.65.0/server.go:1029"
}

The corresponding panic stack trace is included in .error:

panic caught: this is a panic

goroutine 79 [running]:
github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/recovery.recoverFrom({0x1c805a0?, 0xc0001975c0?}, {0x1708580, 0x1c62f60}, 0xc00014354f?)
    /go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware/v2@v2.1.0/interceptors/recovery/interceptors.go:57 +0x65
github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/recovery.UnaryServerInterceptor.func1.1()
    /go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware/v2@v2.1.0/interceptors/recovery/interceptors.go:30 +0x67
panic({0x1708580?, 0x1c62f60?})
    /usr/local/go/src/runtime/panic.go:770 +0x132
github.com/cloudnative-pg/cnpg-i-hello-world/internal/lifecycle.Implementation.reconcileMetadata(...)
    /app/internal/lifecycle/lifecycle.go:78
github.com/cloudnative-pg/cnpg-i-hello-world/internal/lifecycle.Implementation.LifecycleHook({{}}, {0xc000211f80?, 0xc000143708?}, 0xc000697680)
    /app/internal/lifecycle/lifecycle.go:65 +0x91
github.com/cloudnative-pg/cnpg-i/pkg/lifecycle._OperatorLifecycle_LifecycleHook_Handler.func1({0x1c805a0?, 0xc0001975c0?}, {0x18909e0?, 0xc000697680?})
    /go/pkg/mod/github.com/cloudnative-pg/cnpg-i@v0.0.0-20240806095732-9ea12e76a6ee/pkg/lifecycle/operator_lifecycle_grpc.pb.go:129 +0xcb
github.com/grpc-ecosystem/go-grpc-middleware/v2/interceptors/recovery.UnaryServerInterceptor.func1({0x1c805a0?, 0xc0001975c0?}, {0x18909e0?, 0xc000697680?}, 0x17af740?, 0x29d7840?)
    /go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware/v2@v2.1.0/interceptors/recovery/interceptors.go:34 +0x9c
google.golang.org/grpc.getChainUnaryHandler.func1({0x1c805a0, 0xc0001975c0}, {0x18909e0, 0xc000697680})
    /go/pkg/mod/google.golang.org/grpc@v1.65.0/server.go:1196 +0xb2
github.com/cloudnative-pg/cnpg-i-machinery/pkg/pluginhelper.run.loggingUnaryServerInterceptor.func2({0x1c805a0?, 0xc000197560?}, {0x18909e0, 0xc000697680}, 0xc00028e7e0?, 0xc000210080)
    /go/pkg/mod/github.com/leonardoce/cnpg-i-machinery@v0.0.0-20240808133655-263e48aced5e/pkg/pluginhelper/grpc.go:39 +0x53
google.golang.org/grpc.getChainUnaryHandler.func1({0x1c805a0, 0xc000197560}, {0x18909e0, 0xc000697680})
    /go/pkg/mod/google.golang.org/grpc@v1.65.0/server.go:1196 +0xb2
github.com/cloudnative-pg/cnpg-i-machinery/pkg/pluginhelper.run.logFailedRequestsUnaryServerInterceptor.func1({0x1c805a0?, 0xc000197560?}, {0x18909e0?, 0xc000697680?}, 0xc00028e7e0, 0xc000010420?)
    /go/pkg/mod/github.com/leonardoce/cnpg-i-machinery@v0.0.0-20240808133655-263e48aced5e/pkg/pluginhelper/grpc.go:53 +0x69
google.golang.org/grpc.NewServer.chainUnaryServerInterceptors.chainUnaryInterceptors.func1({0x1c805a0, 0xc000197560}, {0x18909e0, 0xc000697680}, 0xc00028e7e0, 0x80?)
    /go/pkg/mod/google.golang.org/grpc@v1.65.0/server.go:1187 +0x85
github.com/cloudnative-pg/cnpg-i/pkg/lifecycle._OperatorLifecycle_LifecycleHook_Handler({0x186c960, 0x29d7840}, {0x1c805a0, 0xc000197560}, 0xc0005cad00, 0xc0000a4440)
    /go/pkg/mod/github.com/cloudnative-pg/cnpg-i@v0.0.0-20240806095732-9ea12e76a6ee/pkg/lifecycle/operator_lifecycle_grpc.pb.go:131 +0x143
google.golang.org/grpc.(*Server).processUnaryRPC(0xc00022cc00, {0x1c805a0, 0xc0001974d0}, {0x1c87880, 0xc0005f4000}, 0xc0005f0240, 0xc0000b5110, 0x2951b38, 0x0)
    /go/pkg/mod/google.golang.org/grpc@v1.65.0/server.go:1379 +0xdf8
google.golang.org/grpc.(*Server).handleStream(0xc00022cc00, {0x1c87880, 0xc0005f4000}, 0xc0005f0240)
    /go/pkg/mod/google.golang.org/grpc@v1.65.0/server.go:1790 +0xe8b
google.golang.org/grpc.(*Server).serveStreams.func2.1()
    /go/pkg/mod/google.golang.org/grpc@v1.65.0/server.go:1029 +0x8b
created by google.golang.org/grpc.(*Server).serveStreams.func2 in goroutine 64
    /go/pkg/mod/google.golang.org/grpc@v1.65.0/server.go:1040 +0x125

The .stracktrace entry is a bit misleading but can be avoided if desired by logging an Info message instead of an Error.

ringerc commented 3 weeks ago

Nice, thanks.