Add logging for unexpected pod eviction errors #1432

dewjam · 2022-02-28T23:27:09Z

1. Issue, if available:
#1414

2. Description of changes:
The eviction API is supposed to only return 429 or 500 status codes when an error is encountered while evicting a pod (per k8s documentation). Today, Karpenter only writes a debug log when a 500 or 429 status code is returned from the eviction API, but doesn't account for the case where an unexpected error/status code is received. This change adds a catch-all so Karpenter will also log unexpected errors from the eviction API.

Edit: This change also introduces structured logging for log emitted by eviction attempts. Also, logs the returned error messages reported by the eviction API for consistency, instead of using custom error messages.

Related to this change, we identified what looks like a bug in the eviction API. In the case where multiple PDBs are found for a pod, the error which is returned correlates to an InternalServerError (500), but the "reason" field excluded. We believe this is the root cause of the problem identified in #1414 . We will be pursuing an upstream fix, but this "catch-all" is also worth implementing to account for unexpected errors.

3. How was this change tested?

Deployed Karpenter including the change to a test EKS cluster
Enabled debug logging
Introduced a conflicting PDB

(edit) Result:

2022-03-03T15:37:19.267Z	DEBUG	controller.eviction	Cannot evict pod as it would violate the pod's disruption budget.	{"commit": "cd8a26f", "pod": "istio-system/istiod-d8576dfdf-hrsnk"}
2022-03-03T15:37:29.274Z	ERROR	controller.eviction	This pod has more than one PodDisruptionBudget, which the eviction subresource does not support.	{"commit": "cd8a26f", "pod": "istio-system/istio-ingressgateway-6559b68fb5-gpm29"}
2022-03-03T15:37:29.327Z	DEBUG	controller.eviction	Evicted pod	{"commit": "cd8a26f", "pod": "istio-system/istiod-d8576dfdf-hrsnk"}

4. Does this change impact docs?

Yes, PR includes docs updates
Yes, issue opened: link to issue
No

By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.

netlify · 2022-02-28T23:27:15Z

✔️ Deploy Preview for karpenter-docs-prod canceled.

🔨 Explore the source changes: 5130600

🔍 Inspect the deploy log: https://app.netlify.com/sites/karpenter-docs-prod/deploys/6221220474fc180008a970c1

njtran

LGTM! Good work

ellistarn · 2022-02-28T23:34:09Z

pkg/controllers/termination/eviction.go

@@ -103,6 +103,7 @@ func (e *EvictionQueue) evict(ctx context.Context, nn types.NamespacedName) bool
 		return true
 	}
 	if err != nil {
+		logging.FromContext(ctx).Debugf("Could not evict pod %s due to an unexpected error: %s", nn.String(), err)


This won't print the error string cleanly. We can also simplify this message.

Suggested change

logging.FromContext(ctx).Debugf("Could not evict pod %s due to an unexpected error: %s", nn.String(), err)

logging.FromContext(ctx).Debugf("Could not evict pod %s, %s", nn.String(), err.Error())

While we're in here, can we move the . from the other log lines?

Sure thing!

both nn.String(), err.Error() can be replaced with nn, err since they have .String they will both turn into strings.

Updated commit with this change.

ellistarn · 2022-02-28T23:49:26Z

pkg/controllers/termination/eviction.go

@@ -103,6 +103,7 @@ func (e *EvictionQueue) evict(ctx context.Context, nn types.NamespacedName) bool
 		return true
 	}
 	if err != nil {
+		logging.FromContext(ctx).Debugf("Could not evict pod %s due to an unexpected error: %s", nn.String(), err)


I think this should be ERROR level.

Unless this is massively noisy. It only happens during misconfiguration, right?

See the difference between lines 95 and 99

Should the 429 violation of PDB be turned up to an info log as well? It may save a round of "turn on debug logs" when troubleshooting why a node won't drain.

Seems to me they all should be Error level. "Error" logs will show up with the default log config, I believe.

One note, we do retry eviction failures, so we will see multiple messages in the log file for each pod.

The 429 seems like a different sort of transient condition to me. It may resolve itself if another pod becomes ready. It doesn't seem right for a log to have repeated error messages when everything is possibly working as expected.

I agree that the multiple PDBs definitely seems like an error level condition. The user has to do something to resolve it.

In some ways the logs/events are the "UI" for Karpenter for users. Maybe a doc defining this would be helpful?

The 429 seems like a different sort of transient condition to me. It may resolve itself if another pod becomes ready. It doesn't seem right for a log to have repeated error messages when everything is possibly working as expected.

This is exactly the reason. We want to avoid spamming INFO logs for normal operation. We're pretty careful about what meets the bar for info. I expect most customers will want to run with DEBUG on and then filter with different tooling. Perhaps we should make DEBUG the default log level in our helm chart.

A 429 should just be debug log IMO. If you run into this error message once, you'll run into it at least 10 times per pod due to the fast exponential backoff, which would make the logs pretty noisy.

A 500 I would think should be info level as well. An unexpected error would make sense to be info level as well.

spring1843 · 2022-02-28T23:51:07Z

pkg/controllers/termination/eviction.go

@@ -103,6 +103,7 @@ func (e *EvictionQueue) evict(ctx context.Context, nn types.NamespacedName) bool
 		return true
 	}
 	if err != nil {
+		logging.FromContext(ctx).Debugf("Could not evict pod %s due to an unexpected error: %s", nn.String(), err)


both nn.String(), err.Error() can be replaced with nn, err since they have .String they will both turn into strings.

pkg/controllers/termination/eviction.go

ellistarn

nice!

njtran previously approved these changes Feb 28, 2022

View reviewed changes

ellistarn reviewed Feb 28, 2022

View reviewed changes

dewjam mentioned this pull request Feb 28, 2022

Expired nodes are stuck in Ready,SchedulingDisabled without any error #1414

Closed

ellistarn reviewed Feb 28, 2022

View reviewed changes

spring1843 suggested changes Feb 28, 2022

View reviewed changes

dewjam dismissed njtran’s stale review via 54defc4 March 1, 2022 00:41

dewjam force-pushed the eviction-logs branch from a9e4680 to 54defc4 Compare March 1, 2022 00:41

dewjam requested a review from spring1843 March 1, 2022 00:57

spring1843 previously approved these changes Mar 1, 2022

View reviewed changes

njtran reviewed Mar 2, 2022

View reviewed changes

pkg/controllers/termination/eviction.go Outdated Show resolved Hide resolved

dewjam dismissed spring1843’s stale review via ab0d4cf March 2, 2022 22:37

dewjam force-pushed the eviction-logs branch 2 times, most recently from ab0d4cf to cd8a26f Compare March 2, 2022 22:41

ellistarn reviewed Mar 2, 2022

View reviewed changes

pkg/controllers/termination/eviction.go Outdated Show resolved Hide resolved

Add logging for unexpected pod eviction errors

5130600

dewjam force-pushed the eviction-logs branch from cd8a26f to 5130600 Compare March 3, 2022 20:16

ellistarn approved these changes Mar 3, 2022

View reviewed changes

dewjam merged commit a3946ce into aws:main Mar 3, 2022

ellistarn mentioned this pull request Mar 4, 2022

Patch logging #1261

Closed

3 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add logging for unexpected pod eviction errors #1432

Add logging for unexpected pod eviction errors #1432

dewjam commented Feb 28, 2022 •

edited

Loading

netlify bot commented Feb 28, 2022 •

edited

Loading

njtran left a comment

ellistarn Feb 28, 2022

dewjam Feb 28, 2022

spring1843 Feb 28, 2022

dewjam Mar 1, 2022

ellistarn Feb 28, 2022

ellistarn Feb 28, 2022

ellistarn Feb 28, 2022

tzneal Mar 1, 2022

dewjam Mar 1, 2022

tzneal Mar 1, 2022 •

edited

Loading

ellistarn Mar 1, 2022

njtran Mar 1, 2022

spring1843 Feb 28, 2022

ellistarn left a comment

	logging.FromContext(ctx).Debugf("Could not evict pod %s due to an unexpected error: %s", nn.String(), err)
	logging.FromContext(ctx).Debugf("Could not evict pod %s, %s", nn.String(), err.Error())

Add logging for unexpected pod eviction errors #1432

Add logging for unexpected pod eviction errors #1432

Conversation

dewjam commented Feb 28, 2022 • edited Loading

netlify bot commented Feb 28, 2022 • edited Loading

njtran left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tzneal Mar 1, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ellistarn left a comment

Choose a reason for hiding this comment

dewjam commented Feb 28, 2022 •

edited

Loading

netlify bot commented Feb 28, 2022 •

edited

Loading

tzneal Mar 1, 2022 •

edited

Loading