Occasional control plane health check failures

[nealharris]

This discussion started at the Buoyant forum here.

While considering the recommendation in that post to revert to the default 3 replicas for the control plane, I noticed that our destination pods have occasional restarts. (Roughly once per day or every other day.)

I found some linkerd logs which happen at the same time as some of the health check (liveness) failures for the pods. I'm not sure how to interpret them, but am following @wmorgan 's suggestion to create an issue here.

Here are some of the logs from one of the destination pods that failed a liveness check. I'm not sure if or how they're related, though. Also, there are tons more logs. Not sure how to find interesting ones, so I'm just grabbing a few for now.

It's probably worth noting that other than when the pods fail health checks, they don't really produce any logs. (Well, that's besides a lot of logs which contain unable to delete server_port_subscribers metric with labels map, which seem to be discussed in #10820.)

We're running on 2.13.5.

What can I do to further investigate or mitigate these restarts?

time="2023-07-16T12:00:51Z" level=info msg="caches synced"

time="2023-07-16T12:00:51Z" level=info msg="waiting for caches to sync"

time="2023-07-16T12:00:51Z" level=info msg="caches synced"

time="2023-07-16T12:00:48Z" level=info msg="waiting for caches to sync"

time="2023-07-16T12:00:48Z" level=info msg="Using default opaque ports: map[25:{} 587:{} 3306:{} 4444:{} 5432:{} 6379:{} 9300:{} 11211:{}]"

time="2023-07-16T12:00:48Z" level=info msg="starting admin server on :9996"

time="2023-07-16T12:00:48Z" level=info msg="running version stable-2.13.5"

/go/pkg/mod/google.golang.org/[email protected]/server.go:964 +0x28a

created by google.golang.org/grpc.(*Server).serveStreams.func1

/go/pkg/mod/google.golang.org/[email protected]/server.go:966 +0x98

google.golang.org/grpc.(*Server).serveStreams.func1.2()

/go/pkg/mod/google.golang.org/[email protected]/server.go:1726 +0x9ea

google.golang.org/grpc.(*Server).handleStream(0xc00045c3c0, {0x22955b8, 0xc0116824e0}, 0xc004efad80, 0x0)

/go/pkg/mod/google.golang.org/[email protected]/server.go:1646 +0x1303

google.golang.org/grpc.(*Server).processStreamingRPC(0xc00045c3c0, {0x22955b8, 0xc0116824e0}, 0xc004efad80, 0xc00079d560, 0x327e8e0, 0x0)

/go/pkg/mod/github.com/grpc-ecosystem/[email protected]/server_metrics.go:121 +0x109

github.com/grpc-ecosystem/go-grpc-prometheus.(*ServerMetrics).StreamServerInterceptor.func1({0x1e68440, 0xc000696600}, {0x2291b00?, 0xc010e00c30}, 0x1af8520?, 0x207a5a0)

/go/pkg/mod/github.com/linkerd/[email protected]/go/destination/destination_grpc.pb.go:172 +0xd0

github.com/linkerd/linkerd2-proxy-api/go/destination._Destination_GetProfile_Handler({0x1e68440?, 0xc000696600}, {0x2291710, 0xc000a0f548})

/linkerd-build/controller/api/destination/server.go:205 +0x412

github.com/linkerd/linkerd2/controller/api/destination.(*server).GetProfile(0xc000696600, 0xc001bee180, {0x2293270, 0xc01168cc00})

/linkerd-build/controller/api/destination/server.go:233 +0x237

github.com/linkerd/linkerd2/controller/api/destination.(*server).getProfileByIP(0xc000696600, {0xc01677a060, 0x57}, {0xc014a8b0a0, 0x10, 0x10}, 0x60?, {0x2293270, 0xc01168cc00})

/linkerd-build/controller/api/destination/server.go:436 +0x6f9

github.com/linkerd/linkerd2/controller/api/destination.(*server).subscribeToEndpointProfile(0xc000696600, 0xc01440d748, 0x1f90, {0x2293270, 0xc01168cc00})

goroutine 472683 [select, 5 minutes]:

/go/pkg/mod/google.golang.org/[email protected]/server.go:964 +0x28a

created by google.golang.org/grpc.(*Server).serveStreams.func1

/go/pkg/mod/google.golang.org/[email protected]/server.go:966 +0x98

google.golang.org/grpc.(*Server).serveStreams.func1.2()

/go/pkg/mod/google.golang.org/[email protected]/server.go:1726 +0x9ea

google.golang.org/grpc.(*Server).handleStream(0xc00045c3c0, {0x22955b8, 0xc00096a000}, 0xc015aa77a0, 0x0)

/go/pkg/mod/google.golang.org/[email protected]/server.go:1646 +0x1303

google.golang.org/grpc.(*Server).processStreamingRPC(0xc00045c3c0, {0x22955b8, 0xc00096a000}, 0xc015aa77a0, 0xc00079d560, 0x327e8e0, 0x0)

/go/pkg/mod/github.com/grpc-ecosystem/[email protected]/server_metrics.go:121 +0x109

github.com/grpc-ecosystem/go-grpc-prometheus.(*ServerMetrics).StreamServerInterceptor.func1({0x1e68440, 0xc000696600}, {0x2291b00?, 0xc00f946690}, 0x1af8520?, 0x207a5a0)

/go/pkg/mod/github.com/linkerd/[email protected]/go/destination/destination_grpc.pb.go:172 +0xd0

github.com/linkerd/linkerd2-proxy-api/go/destination._Destination_GetProfile_Handler({0x1e68440?, 0xc000696600}, {0x2291710, 0xc01965a048})

/linkerd-build/controller/api/destination/server.go:205 +0x412

github.com/linkerd/linkerd2/controller/api/destination.(*server).GetProfile(0xc000696600, 0xc01739aea0, {0x2293270, 0xc010fc9d50})

/linkerd-build/controller/api/destination/server.go:237 +0x38b

github.com/linkerd/linkerd2/controller/api/destination.(*server).getProfileByIP(0xc000696600, {0xc01b6908a0, 0x53}, {0xc016ae3290, 0x10, 0x10}, 0x60?, {0x2293270, 0xc010fc9d50})

/linkerd-build/controller/api/destination/server.go:314 +0x82d

github.com/linkerd/linkerd2/controller/api/destination.(*server).subscribeToServiceProfile(0xc000696600, {{0xc000783ad7?, 0x57580d?}, {0xc00048b680?, 0x110?}}, {0xc01b6908a0, 0x53}, {0xc013b58500, 0x35}, 0x138d, ...)

/linkerd-build/controller/api/destination/server.go:363 +0x7c5

github.com/linkerd/linkerd2/controller/api/destination.(*server).subscribeToServicesWithContext(0xc000696600, {0xc013b58500, 0x35}, {{0xc016ae32b8?, 0xc014fe1fa0?}, {0xc013b58540?, 0xc010a227c0?}}, {0x226fb40?, 0xc0163a6080}, 0xc01b6907e0, ...)```

[nealharris]

Here's another hunk of logs from a different time that look interesting as well.

goroutine 84 [running]:

[signal SIGSEGV: segmentation violation code=0x1 addr=0x18 pc=0x18119cb]

panic: runtime error: invalid memory address or nil pointer dereference

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

time="2023-07-20T00:18:05Z" level=info msg="waiting for caches to sync"

time="2023-07-20T00:18:05Z" level=info msg="Using default opaque ports: map[25:{} 587:{} 3306:{} 4444:{} 5432:{} 6379:{} 9300:{} 11211:{}]"

time="2023-07-20T00:18:05Z" level=info msg="starting admin server on :9996"

time="2023-07-20T00:18:05Z" level=info msg="running version stable-2.13.5"

/go/pkg/mod/k8s.io/[email protected]/pkg/util/wait/wait.go:70 +0x85

created by k8s.io/apimachinery/pkg/util/wait.(*Group).Start

/go/pkg/mod/k8s.io/[email protected]/pkg/util/wait/wait.go:72 +0x5a

k8s.io/apimachinery/pkg/util/wait.(*Group).Start.func1()

/go/pkg/mod/k8s.io/[email protected]/tools/cache/shared_informer.go:967 +0x6b

k8s.io/client-go/tools/cache.(*processorListener).run(0xc000446f30?)

/go/pkg/mod/k8s.io/[email protected]/pkg/util/wait/backoff.go:161

k8s.io/apimachinery/pkg/util/wait.Until(...)

/go/pkg/mod/k8s.io/[email protected]/pkg/util/wait/backoff.go:204 +0x89

k8s.io/apimachinery/pkg/util/wait.JitterUntil(0x0?, 0x3b9aca00, 0x0, 0x0?, 0x0?)

/go/pkg/mod/k8s.io/[email protected]/pkg/util/wait/backoff.go:227 +0xb6

k8s.io/apimachinery/pkg/util/wait.BackoffUntil(0x46e427?, {0x2271400, 0xc0005ba030}, 0x1, 0xc0005b8060)

/go/pkg/mod/k8s.io/[email protected]/pkg/util/wait/backoff.go:226 +0x3e

k8s.io/apimachinery/pkg/util/wait.BackoffUntil.func1(0x32ed3a0?)

/go/pkg/mod/k8s.io/[email protected]/tools/cache/shared_informer.go:971 +0xfc

k8s.io/client-go/tools/cache.(*processorListener).run.func1()

/go/pkg/mod/k8s.io/[email protected]/tools/cache/controller.go:250

k8s.io/client-go/tools/cache.ResourceEventHandlerFuncs.OnUpdate(...)

/linkerd-build/controller/api/destination/watcher/endpoints_watcher.go:164 +0x2d

github.com/linkerd/linkerd2/controller/api/destination/watcher.NewEndpointsWatcher.func2({0x406878?, 0xc00081a2a0?}, {0x1f15fa0?, 0xc0005f5500?})

/linkerd-build/controller/api/destination/watcher/endpoints_watcher.go:416 +0x105

github.com/linkerd/linkerd2/controller/api/destination/watcher.(*EndpointsWatcher).addServer(0xc000814780, {0x1f15fa0?, 0xc0005f5500})

/linkerd-build/controller/api/destination/watcher/endpoints_watcher.go:602 +0x125

github.com/linkerd/linkerd2/controller/api/destination/watcher.(*servicePublisher).updateServer(0xc000132690, 0xc0005f5500, 0xf0?)

/linkerd-build/controller/api/destination/watcher/endpoints_watcher.go:1103 +0x22b

github.com/linkerd/linkerd2/controller/api/destination/watcher.(*portPublisher).updateServer(0xc001882000, 0xc0005f5500, {0x22939f0, 0xc0080a9b90}, 0x1)

/usr/local/go/src/runtime/panic.go:884 +0x212

panic({0x1c7c7c0, 0x3271490})

/go/pkg/mod/k8s.io/[email protected]/pkg/util/runtime/runtime.go:56 +0xd7

k8s.io/apimachinery/pkg/util/runtime.HandleCrash({0x0, 0x0, 0xc0008147a4?})

[alpeb]

Thanks for the detailed report @nealharris. This indeed uncovers a race condition that I'm tracking in #11163. When we fix this in the main branch it should be a good candidate to get back-ported into 2.13.

[nealharris]

Thank you for the update!