Error when etcd3 watch finds delete event with nil prevKV #76675

ryanmcnamara · 2019-04-16T20:09:58Z

What type of PR is this?

Uncomment only one /kind <> line, hit enter to put that in a new line, and remove leading whitespaces from that line:

/kind bug

What this PR does / why we need it:

See #76624 (comment), taking half of that suggestion (for now), which is to end the watch when a delete event does not have a prevKV

Does this PR introduce a user-facing change?:

Fixes an error with stuck informers when an etcd watch receives update or delete events with missing data

k8s-ci-robot · 2019-04-16T20:10:06Z

Hi @ryanmcnamara. Thanks for your PR.

I'm waiting for a kubernetes member to verify that this patch is reasonable to test. If it is, they should reply with /ok-to-test on its own line. Until that is done, I will not automatically test new commits in this PR, but the usual testing commands by org members will still work. Regular contributors should join the org to skip this step.

Once the patch is verified, the new status will be reflected by the ok-to-test label.

I understand the commands that are listed here.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

ryanmcnamara · 2019-04-16T20:16:20Z

@liggitt, should we do the same thing for "update" events, I believe in this part of the code that would be events that !isDeleted && !isCreated?

ryanmcnamara · 2019-04-16T20:17:17Z

I'll be testing this change out on our stack that initially ran into #76624 using this branch: https://github.com/ryanmcnamara/kubernetes/tree/rm/error-on-nil-event-demo

liggitt · 2019-04-16T20:19:19Z

@liggitt, should we do the same thing for "update" events, I believe in this part of the code that would be events that !isDeleted && !isCreated?

I believe so, yes

liggitt · 2019-04-16T20:24:14Z

staging/src/k8s.io/apiserver/pkg/storage/etcd3/event.go

@@ -53,5 +54,9 @@ func parseEvent(e *clientv3.Event) *event {
 	if e.PrevKv != nil {
 		ret.prevValue = e.PrevKv.Value
 	}
-	return ret
+	if ret.isDeleted && ret.prevValue == nil {


if the previous value existed, but was a zero-length byte array, does this show up as nil here? do we know if e.PrevKv as nil as well when we encountered this?

if the previous value existed, but was a zero-length byte array, does this show up as nil here?

I expect it would show up as the zero length byte array

do we know if e.PrevKv as nil as well when we encountered this?

All I can be certain is that when I encountered this either e.PrevKv was nil or e.PrevKv.Value was nil. I expect that e.PrevKv was nil though, given the info I had on compaction taking place and this comment

I expect it would show up as the zero length byte array

expectations are funny things... if it uses protobuf, zero-length and nil arrays can be serialized identically

Ok, I was mostly trying to fix the specific problem I encountered, to error here if and only if the prev value was nil, and not erroring on the empty array as I'm not sure we have that guarantee here.

Do you think this should error for both? error if len(ret.preValue)==0?

if e.PrevKv is nil, that seems like a much clearer indicator of a problem

ryanmcnamara · 2019-04-16T22:24:19Z

Will deploy this change as is now, wait for the repro (which could take several days) and confirm that it handles it better

fedebongio · 2019-04-18T20:07:12Z

/assign @jpbetz
/cc @wenjiaswe @jingyih

k8s-ci-robot · 2019-04-18T20:07:15Z

@fedebongio: GitHub didn't allow me to request PR reviews from the following users: jingyih.

Note that only kubernetes members and repo collaborators can review this PR, and authors cannot review their own PRs.

In response to this:

/assign @jpbetz
/cc @wenjiaswe @jingyih

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

ryanmcnamara · 2019-04-25T15:45:35Z

The conditions of the issue repro'd and this change did the correct thing, spotting the nil prevKV and closing the watch.

Full log line:

2019-04-24 02:03:49.757 watch chan error: etcd event was not a create and has a nil prevKV, key: /registry/pods/ns1/pod1, modRevision: 4842145275, isDelete false k8s.io/kubernetes/kube-apiserver/watcher.go:215

Here is a graph of the number of pods an informer is holding

The metrics were obtained by making a separate informer per apiserver. As you can see, updates seem to halt for some time, but recovers immediately when the watch is closed.

While this graph is secondary (shows the view of the problem from a client of the apiserver's perspective) it's still useful in understanding the timeline.

liggitt · 2019-04-25T19:11:22Z

nice graph! do you have any insight as to what happened between 1:55 and 2:00 (based on apiserver or etcd logs)? do you know which apiserver/etcd member was affected? anything suspect in the logs for that member?

ryanmcnamara · 2019-04-25T20:52:45Z

The event started exactly when the kube controller manager leader switched (this happens at 1:55). The apiserver it's now hitting is the impacted one. That's how this issue has always reproduced.

Looking at etcd logs and metrics I don't see anything interesting.

Each time this happens I notice load going quite high on the master host, but only around .6 or so normalized at the start of the incident, going to 1 briefly, here's a screenshot (note the 32 vcpu machines being used)

I don't really think this is the issue though, because the load stays well below 1 normalized

I can take another look at the logs and see if I find anything

Do you want to continue debugging on the issue? Seems like this pr is useful regardless of what's causing the delay in events.

liggitt · 2019-04-25T21:32:33Z

staging/src/k8s.io/apiserver/pkg/storage/etcd3/event.go

+func parseEvent(e *clientv3.Event) (*event, error) {
+	if !e.IsCreate() && e.PrevKv == nil {
+		// If the previous value is nil, error. One example of how this is possible is if the previous value has been compacted already.
+		return nil, fmt.Errorf("etcd event was not a create and has a nil prevKV, key: %s, modRevision: %d, isDelete %v", string(e.Kv.Key), e.Kv.ModRevision, e.Type == clientv3.EventTypeDelete)


@jpbetz can you sanity check that all non-create events should have a PrevKv set?

(we only use this method in one place, on a watch, started with the PrevKv option)

opts := []clientv3.OpOption{clientv3.WithRev(wc.initialRev + 1), clientv3.WithPrevKV()}

Looks like etcd not providing a prevKV if it was compacted was intentional. See my comment here: #76624 (comment)

I'm betting this really is due to compaction. It looks like we're using clientv3.WithPrevKV correctly.

staging/src/k8s.io/apiserver/pkg/storage/etcd3/event.go

ryanmcnamara · 2019-04-26T00:16:28Z

@liggitt done

liggitt · 2019-04-26T03:07:58Z

/priority critical-urgent
/ok-to-test

liggitt · 2019-04-26T06:22:16Z

looks like hack/update-bazel.sh is needed

jpbetz · 2019-04-26T06:36:40Z

/lgtm

liggitt · 2019-04-29T20:03:47Z

/lgtm
/approve

k8s-ci-robot · 2019-04-29T20:04:15Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: liggitt, ryanmcnamara

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~staging/src/k8s.io/apiserver/pkg/storage/OWNERS~~ [liggitt]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

liggitt · 2019-04-29T20:04:32Z

once this merges, can you pick it to 1.12, 1.13, and 1.14 (using hack/cherry_pick_pull.sh)?

liggitt · 2019-05-03T14:20:30Z

picks opened

…5-upstream-release-1.12 Automated cherry pick of #76675: Error when etcd3 watch finds delete event with nil prevKV

…5-upstream-release-1.14 Automated cherry pick of #76675: Error when etcd3 watch finds delete event with nil prevKV

…5-upstream-release-1.13 Automated cherry pick of #76675: Error when etcd3 watch finds delete event with nil prevKV

k8s-ci-robot requested review from madhusudancs and timothysc April 16, 2019 20:11

ryanmcnamara mentioned this pull request Apr 16, 2019

Pod reflector getting delete events with nil object #76624

Closed

liggitt reviewed Apr 16, 2019

View reviewed changes

k8s-ci-robot added size/L Denotes a PR that changes 100-499 lines, ignoring generated files. and removed size/M Denotes a PR that changes 30-99 lines, ignoring generated files. labels Apr 16, 2019

k8s-ci-robot assigned jpbetz Apr 18, 2019

k8s-ci-robot requested a review from wenjiaswe April 18, 2019 20:07

liggitt reviewed Apr 25, 2019

View reviewed changes

staging/src/k8s.io/apiserver/pkg/storage/etcd3/event.go Outdated Show resolved Hide resolved

ryanmcnamara force-pushed the rm/error-on-nil-master branch from 21a74cd to 7406fcc Compare April 26, 2019 00:16

ryanmcnamara force-pushed the rm/error-on-nil-master branch from 7406fcc to bf65c0a Compare April 26, 2019 03:55

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Apr 26, 2019

ryanmcnamara force-pushed the rm/error-on-nil-master branch from bf65c0a to c6eb078 Compare April 26, 2019 15:02

k8s-ci-robot removed the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Apr 26, 2019

Error when etcd3 watch finds delete event with nil prevKV

5043806

ryanmcnamara force-pushed the rm/error-on-nil-master branch from c6eb078 to 5043806 Compare April 26, 2019 16:52

k8s-ci-robot assigned liggitt Apr 29, 2019

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Apr 29, 2019

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Apr 29, 2019

k8s-ci-robot merged commit 5ccda18 into kubernetes:master Apr 29, 2019

k8s-ci-robot added a commit that referenced this pull request May 4, 2019

Merge pull request #77395 from liggitt/automated-cherry-pick-of-#7667…

677bb50

…5-upstream-release-1.12 Automated cherry pick of #76675: Error when etcd3 watch finds delete event with nil prevKV

k8s-ci-robot added a commit that referenced this pull request May 6, 2019

Merge pull request #77393 from liggitt/automated-cherry-pick-of-#7667…

09f3af0

…5-upstream-release-1.14 Automated cherry pick of #76675: Error when etcd3 watch finds delete event with nil prevKV

k8s-ci-robot added a commit that referenced this pull request May 7, 2019

Merge pull request #77394 from liggitt/automated-cherry-pick-of-#7667…

978a0a8

…5-upstream-release-1.13 Automated cherry pick of #76675: Error when etcd3 watch finds delete event with nil prevKV

mengqiy mentioned this pull request Feb 3, 2024

APIServer watchcache lost events #123072

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Error when etcd3 watch finds delete event with nil prevKV #76675

Error when etcd3 watch finds delete event with nil prevKV #76675

ryanmcnamara commented Apr 16, 2019 •

edited by liggitt

Loading

k8s-ci-robot commented Apr 16, 2019

ryanmcnamara commented Apr 16, 2019 •

edited

Loading

ryanmcnamara commented Apr 16, 2019

liggitt commented Apr 16, 2019

liggitt Apr 16, 2019

ryanmcnamara Apr 16, 2019

liggitt Apr 16, 2019

ryanmcnamara Apr 16, 2019

liggitt Apr 16, 2019

ryanmcnamara commented Apr 16, 2019

fedebongio commented Apr 18, 2019

k8s-ci-robot commented Apr 18, 2019

ryanmcnamara commented Apr 25, 2019

liggitt commented Apr 25, 2019

ryanmcnamara commented Apr 25, 2019

liggitt Apr 25, 2019

liggitt Apr 25, 2019

jpbetz Apr 26, 2019 •

edited

Loading

ryanmcnamara commented Apr 26, 2019

liggitt commented Apr 26, 2019

liggitt commented Apr 26, 2019

jpbetz commented Apr 26, 2019

liggitt commented Apr 29, 2019

k8s-ci-robot commented Apr 29, 2019

liggitt commented Apr 29, 2019 •

edited

Loading

liggitt commented May 3, 2019

Error when etcd3 watch finds delete event with nil prevKV #76675

Error when etcd3 watch finds delete event with nil prevKV #76675

Conversation

ryanmcnamara commented Apr 16, 2019 • edited by liggitt Loading

k8s-ci-robot commented Apr 16, 2019

ryanmcnamara commented Apr 16, 2019 • edited Loading

ryanmcnamara commented Apr 16, 2019

liggitt commented Apr 16, 2019

liggitt Apr 16, 2019

Choose a reason for hiding this comment

ryanmcnamara Apr 16, 2019

Choose a reason for hiding this comment

liggitt Apr 16, 2019

Choose a reason for hiding this comment

ryanmcnamara Apr 16, 2019

Choose a reason for hiding this comment

liggitt Apr 16, 2019

Choose a reason for hiding this comment

ryanmcnamara commented Apr 16, 2019

fedebongio commented Apr 18, 2019

k8s-ci-robot commented Apr 18, 2019

ryanmcnamara commented Apr 25, 2019

liggitt commented Apr 25, 2019

ryanmcnamara commented Apr 25, 2019

liggitt Apr 25, 2019

Choose a reason for hiding this comment

liggitt Apr 25, 2019

Choose a reason for hiding this comment

jpbetz Apr 26, 2019 • edited Loading

Choose a reason for hiding this comment

ryanmcnamara commented Apr 26, 2019

liggitt commented Apr 26, 2019

liggitt commented Apr 26, 2019

jpbetz commented Apr 26, 2019

liggitt commented Apr 29, 2019

k8s-ci-robot commented Apr 29, 2019

liggitt commented Apr 29, 2019 • edited Loading

liggitt commented May 3, 2019

ryanmcnamara commented Apr 16, 2019 •

edited by liggitt

Loading

ryanmcnamara commented Apr 16, 2019 •

edited

Loading

jpbetz Apr 26, 2019 •

edited

Loading

liggitt commented Apr 29, 2019 •

edited

Loading