Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix concurrent map writes error in kube-apiserver #106045

Merged
merged 1 commit into from Nov 10, 2021

Conversation

chenlinx17
Copy link
Contributor

What type of PR is this?

/kind bug

What this PR does / why we need it:

this PR adds a sync.mutex in auditHandler to protect map audit.Event.Annotations from concurrent writes

Which issue(s) this PR fixes:

Fixes a concurrent map writes bug when recording audit event in the delete-collection scenario

fatal error: concurrent map writes

goroutine 10670 [running]:
runtime.throw({0x5648d2156ef9, 0xc010a4a4e0})
        runtime/panic.go:1198 +0x71 fp=0xc00a472f20 sp=0xc00a472ef0 pc=0x5648cf1e3371
runtime.mapassign_faststr(0x5648d2e8ac00, 0x65, {0xc0077382c0, 0x31})
        runtime/map_faststr.go:211 +0x39c fp=0xc00a472f88 sp=0xc00a472f20 pc=0x5648cf1c0a1c
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/audit.LogAnnotation(0xc006f943c0, {0xc0077382c0, 0x31}, {0xc0154fe150, 0x65})
        k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/audit/request.go:235 +0x325 fp=0xc00a473040 sp=0xc00a472f88 pc=0x5648d0066dc5
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/admission.auditHandler.logAnnotations({{0x5648d36ed3a0, 0xc000e044e0}, 0xc006f943c0}, {0x5648d3880100, 0xc00ab29560})
        k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/admission/audit.go:94 +0x1c5 fp=0xc00a4730e8 sp=0xc00a473040 pc=0x5648d006de85
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/admission.auditHandler.Admit({{0x5648d36ed3a0, 0xc000e044e0}, 0xc006f943c0}, {0x5648d37d2fb8, 0xc007a415f0}, {0x5648d3880100, 0xc00ab29560}, {0x5648d380ea78, 0xc003724ea0})
        k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/admission/audit.go:58 +0x13c fp=0xc00a473158 sp=0xc00a4730e8 pc=0x5648d006d97c
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/admission.(*auditHandler).Admit(0xc00e871db8, {0x5648d37d2fb8, 0xc007a415f0}, {0x5648d3880100, 0xc00ab29560}, {0x5648d380ea78, 0xc003724ea0})
        <autogenerated>:1 +0x85 fp=0xc00a4731b0 sp=0xc00a473158 pc=0x5648d0071785
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/registry/rest.AdmissionToValidateObjectDeleteFunc.func1({0x5648d37d2fb8, 0xc007a415f0}, {0x5648d37b3b00, 0xc00b4cb8c0})
        k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/registry/rest/delete.go:172 +0x611 fp=0xc00a4733e0 sp=0xc00a4731b0 pc=0x5648d024f211
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/registry/generic/registry.(*Store).updateForGracefulDeletionAndFinalizers.func1({0x5648d37b3b00, 0xc00b4cb8c0})
        k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/registry/generic/registry/store.go:819 +0xbb fp=0xc00a4734b8 sp=0xc00a4733e0 pc=0x5648d04f6cfb
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/storage.SimpleUpdate.func1({0x5648d37b3b00, 0xc00b4cb8c0}, {0xc0101782e0, 0xc012d285a0})
        k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/storage/util.go:33 +0x27 fp=0xc00a4734d8 sp=0xc00a4734b8 pc=0x5648d0246d07
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/storage/etcd3.(*store).updateState(0xc0028c27e0, 0xc0101782e0, 0x20)
        k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/storage/etcd3/store.go:853 +0x3e fp=0xc00a473538 sp=0xc00a4734d8 pc=0x5648d033ddfe
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/storage/etcd3.(*store).GuaranteedUpdate(0xc0028c27e0, {0x5648d37d2fb8, 0xc007a415f0}, {0xc011a36ee8, 0x17}, {0x5648d37b3b00, 0xc00b46f8c0}, 0x0, 0x1, 0xc00a2bd860, ...)
        k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/storage/etcd3/store.go:296 +0x5c7 fp=0xc00a473b50 sp=0xc00a473538 pc=0x5648d0338687
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/storage/cacher.(*Cacher).GuaranteedUpdate(0xc0028e8000, {0x5648d37d2fb8, 0xc007a415f0}, {0xc011a36ee8, 0x17}, {0x5648d37b3b00, 0xc00b46f8c0}, 0x85, 0x5648d34fb820, 0xc00a2bd860, ...)
        k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/storage/cacher/cacher.go:743 +0x1d3 fp=0xc00a473bf8 sp=0xc00a473b50 pc=0x5648d04e4553
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/registry/generic/registry.(*DryRunnableStorage).GuaranteedUpdate(0x1e, {0x5648d37d2fb8, 0xc007a415f0}, {0xc011a36ee8, 0x0}, {0x5648d37b3b00, 0xc00b46f8c0}, 0x0, 0x0, 0xc00a2bd860, ...)
        k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/registry/generic/registry/dryrun.go:101 +0x1da fp=0xc00a473c78 sp=0xc00a473bf8 pc=0x5648d04f247a
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/registry/generic/registry.(*Store).updateForGracefulDeletionAndFinalizers(0xc0015de480, {0x5648d37d2fb8, 0xc007a415f0}, {0xc0098fdf10, 0xe}, {0xc011a36ee8, 0x17}, 0xc00333f2c0, {0x0, 0x0}, ...)
        k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/registry/generic/registry/store.go:812 +0x2cf fp=0xc00a473d40 sp=0xc00a473c78 pc=0x5648d04f698f
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/registry/generic/registry.(*Store).Delete(0xc0015de480, {0x5648d37d2fb8, 0xc007a415f0}, {0xc0098fdf10, 0xe}, 0x5648cf6a8adb, 0xc00333f2c0)
        k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/registry/generic/registry/store.go:936 +0x3b3 fp=0xc00a473e90 sp=0xc00a473d40 pc=0x5648d04f73d3
k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/registry/generic/registry.(*Store).DeleteCollection.func2()
        k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/registry/generic/registry/store.go:1058 +0x205 fp=0xc00a473fe0 sp=0xc00a473e90 pc=0x5648d04f80a5
runtime.goexit()
        runtime/asm_amd64.s:1581 +0x1 fp=0xc00a473fe8 sp=0xc00a473fe0 pc=0x5648cf2169a1
created by k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/registry/generic/registry.(*Store).DeleteCollection
        k8s.io/kubernetes/vendor/k8s.io/apiserver/pkg/registry/generic/registry/store.go:1045 +0x2df

Special notes for your reviewer:

this bug trigger condition:
1、enabled audit log for kube-apiserver
2、enabled multi-goroutine for delete collection (--delete-collection-workers > 1)

Does this PR introduce a user-facing change?

NONE

Additional documentation e.g., KEPs (Kubernetes Enhancement Proposals), usage docs, etc.:


@k8s-ci-robot k8s-ci-robot added kind/bug Categorizes issue or PR as related to a bug. size/S Denotes a PR that changes 10-29 lines, ignoring generated files. do-not-merge/release-note-label-needed Indicates that a PR should not merge because it's missing one of the release note labels. labels Nov 1, 2021
@k8s-ci-robot
Copy link
Contributor

Thanks for your pull request. Before we can look at your pull request, you'll need to sign a Contributor License Agreement (CLA).

📝 Please follow instructions at https://git.k8s.io/community/CLA.md#the-contributor-license-agreement to sign the CLA.

It may take a couple minutes for the CLA signature to be fully registered; after that, please reply here with a new comment and we'll verify. Thanks.


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. I understand the commands that are listed here.

@k8s-ci-robot k8s-ci-robot added cncf-cla: no Indicates the PR's author has not signed the CNCF CLA. do-not-merge/needs-sig Indicates an issue or PR lacks a `sig/foo` label and requires one. needs-triage Indicates an issue or PR lacks a `triage/foo` label and requires one. labels Nov 1, 2021
@k8s-ci-robot
Copy link
Contributor

Welcome @chenlinx17!

It looks like this is your first PR to kubernetes/kubernetes 🎉. Please refer to our pull request process documentation to help your PR have a smooth ride to approval.

You will be prompted by a bot to use commands during the review process. Do not be afraid to follow the prompts! It is okay to experiment. Here is the bot commands documentation.

You can also check if kubernetes/kubernetes has its own contribution guidelines.

You may want to refer to our testing guide if you run into trouble with your tests not passing.

If you are having difficulty getting your pull request seen, please follow the recommended escalation practices. Also, for tips and tricks in the contribution process you may want to read the Kubernetes contributor cheat sheet. We want to make sure your contribution gets all the attention it needs!

Thank you, and welcome to Kubernetes. 😃

@k8s-ci-robot
Copy link
Contributor

Hi @chenlinx17. 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.

@k8s-ci-robot k8s-ci-robot added needs-ok-to-test Indicates a PR that requires an org member to verify it is safe to test. needs-priority Indicates a PR lacks a `priority/foo` label and requires one. area/apiserver sig/api-machinery Categorizes an issue or PR as relevant to SIG API Machinery. and removed do-not-merge/needs-sig Indicates an issue or PR lacks a `sig/foo` label and requires one. labels Nov 1, 2021
@tanjing2020
Copy link
Contributor

/release-note-none
/ok-to-test

@k8s-ci-robot k8s-ci-robot added ok-to-test Indicates a non-member PR verified by an org member that is safe to test. release-note-none Denotes a PR that doesn't merit a release note. and removed needs-ok-to-test Indicates a PR that requires an org member to verify it is safe to test. do-not-merge/release-note-label-needed Indicates that a PR should not merge because it's missing one of the release note labels. labels Nov 2, 2021
@chenlinx17
Copy link
Contributor Author

the CLA has been signed.

@k8s-ci-robot k8s-ci-robot added cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. and removed cncf-cla: no Indicates the PR's author has not signed the CNCF CLA. labels Nov 2, 2021
@chenlinx17
Copy link
Contributor Author

/cc @hzxuzhonghu @sttts

@chenlinx17
Copy link
Contributor Author

/priority important-soon

@k8s-ci-robot k8s-ci-robot added priority/important-soon Must be staffed and worked on either currently, or very soon, ideally in time for the next release. and removed needs-priority Indicates a PR lacks a `priority/foo` label and requires one. labels Nov 2, 2021
@fedebongio
Copy link
Contributor

/assign @tkashem
/triage accepted

Copy link
Contributor

@tkashem tkashem left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

we have concurrent execution overlap of the handler chain, so ideally we want to move the lock inside audit.LogAnnotation so that the annotations map is always protected, not just from multiple deletion go routines. But this is not trivial, we can address this is a follow up PR.

// LogAnnotation fills in the Annotations according to the key value pair.
func LogAnnotation(ae *auditinternal.Event, key, value string) {
if ae == nil || ae.Level.Less(auditinternal.LevelMetadata) {
return
}
if ae.Annotations == nil {
ae.Annotations = make(map[string]string)
}
if v, ok := ae.Annotations[key]; ok && v != value {
klog.Warningf("Failed to set annotations[%q] to %q for audit:%q, it has already been set to %q", key, value, ae.AuditID, ae.Annotations[key])
return
}
ae.Annotations[key] = value
}

@@ -28,6 +29,10 @@ import (
type auditHandler struct {
Interface
ae *auditinternal.Event
// Indicate whether concurrency protection is required
concurrencyProtection bool
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

i think it's not very costly to always have concurrency on - so i would recommend removing the bool

Copy link
Contributor Author

@chenlinx17 chenlinx17 Nov 5, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I have checked all the call points of the audit.LogAnnotation. Currently, only calls from auditHandler trigger this problem.
If I move the lock inside audit.LogAnnotation, Theoretically, it would be better to declare the lock in auditinternal.Event, but I haven't seen sync.Mutex declared in types.go before, should I declare the lock as a global variable?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

but I haven't seen sync.Mutex declared in types.go before, should I declare the lock as a global variable?

you are right, the types do not have any internal states. moving the lock inside audit.LogAnnotation is not trivial so let's address it in a separate PR.

I think what you have right now should resolve the panic we are seeing. We also need to back port this PR to supported releases, so let's keep it short so it is back portable.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

should I declare the lock as a global variable?

that would not be at request scoped, so all requests in flight would fight for this lock which is not good :)

@tkashem
Copy link
Contributor

tkashem commented Nov 5, 2021

I was looking at the test TestWithAudit - if you run this test with race enabled do you see this panic? if not, then can you add a test with which you can reproduce this panic due to concurrent write? This way we can verify that your solution works.

@k8s-ci-robot k8s-ci-robot added size/M Denotes a PR that changes 30-99 lines, ignoring generated files. and removed size/S Denotes a PR that changes 10-29 lines, ignoring generated files. labels Nov 8, 2021
@chenlinx17
Copy link
Contributor Author

I was looking at the test TestWithAudit - if you run this test with race enabled do you see this panic? if not, then can you add a test with which you can reproduce this panic due to concurrent write? This way we can verify that your solution works.

I've added a testcase to simulate a DeleteCollection scenario. Then it turns out that the previous modification doesn't work because the auditHandler uses the value receiver, I've redacted it, thank you very much.

@tkashem
Copy link
Contributor

tkashem commented Nov 8, 2021

so, when you run delete collection with multiple go routines - each delete worker is going to add the same annotations in to the attributes, from there they will end up in the ae (audit event) object of the DELETECOLLECTION request.

audit.LogAnnotation(handler.ae, key, value)

so looks like you should see the following warning:

if v, ok := ae.Annotations[key]; ok && v != value {
klog.Warningf("Failed to set annotations[%q] to %q for audit:%q, it has already been set to %q", key, value, ae.AuditID, ae.Annotations[key])
return
}

have you run into this when you ran with multiple go routines in your dev environment?

@@ -28,6 +29,8 @@ import (
type auditHandler struct {
Interface
ae *auditinternal.Event
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: you are protecting ae, as a convention i would suggest moving the lock

type auditHandler struct {
   ...

   mutex sync.Mutex
   ae *auditinternal.Event   
}

@@ -28,6 +29,8 @@ import (
type auditHandler struct {
Interface
ae *auditinternal.Event
// Mutex protects the annotations of ae
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: to protect the 'Annotations' map of the audit event from concurrent writes

// Simulate the scenario store.DeleteCollection
workers := 5
toProcess := make(chan int, 2*workers)
go func() {
Copy link
Contributor

@tkashem tkashem Nov 8, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

if we have one go routine that reads ae.Annotations and another go routine that writes to it via auditHandler.Admit - shouldn't that be enough for showing the data race? Just thinking out loud on a more simple version of the test that will expose the data race.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Since my lock protection is in auditHandler.logAnnotations, the test requires both coroutines to read/write ae.Annotations via the auditHandler.Admit or auditHandler.Validate.

@chenlinx17
Copy link
Contributor Author

chenlinx17 commented Nov 9, 2021

have you run into this when you ran with multiple go routines in your dev environment?

Yes, I did. In fact, when I delete nodes in batches, there is a high probability that this bug occurs. I think the reason is that I add the webhook admission for node update request, which will trigger Attributes.AddAnnotation .
In addition, I think the warning you mentioned has no impact on the current modification.

Copy link
Contributor

@tkashem tkashem left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

looks good to me, please add the TODO requested.

@@ -27,7 +28,9 @@ import (
// auditHandler logs annotations set by other admission handlers
type auditHandler struct {
Interface
ae *auditinternal.Event
// to protect the 'Annotations' map of the audit event from concurrent writes
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

TODO: move the lock near the Annotations field of the of the audit events so it is always protected from concurrent access.

@tkashem
Copy link
Contributor

tkashem commented Nov 10, 2021

/lgtm

Thanks!

@tkashem
Copy link
Contributor

tkashem commented Nov 10, 2021

(for approval)

/assign @sttts

@k8s-ci-robot k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Nov 10, 2021
@tkashem
Copy link
Contributor

tkashem commented Nov 10, 2021

@chenlinx17 once this merges, i think we need to back port it.

@sttts
Copy link
Contributor

sttts commented Nov 10, 2021

/lgtm
/approve

@k8s-ci-robot
Copy link
Contributor

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: chenlinx17, sttts

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:

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

@k8s-ci-robot k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Nov 10, 2021
@k8s-ci-robot k8s-ci-robot merged commit d67cbcb into kubernetes:master Nov 10, 2021
@k8s-ci-robot k8s-ci-robot added this to the v1.23 milestone Nov 10, 2021
k8s-ci-robot added a commit that referenced this pull request Jan 15, 2022
Cherry pick #106045 to 1.22: Fix concurrent map writes error in kube-apiserver
k8s-ci-robot added a commit that referenced this pull request Jan 15, 2022
Cherry pick #106045 to 1.21: Fix concurrent map writes error in kube-apiserver
k8s-ci-robot added a commit that referenced this pull request Jan 15, 2022
Cherry pick #106045 to 1.20: Fix concurrent map writes error in kube-apiserver
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
approved Indicates a PR has been approved by an approver from all required OWNERS files. area/apiserver cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. kind/bug Categorizes issue or PR as related to a bug. lgtm "Looks good to me", indicates that a PR is ready to be merged. ok-to-test Indicates a non-member PR verified by an org member that is safe to test. priority/important-soon Must be staffed and worked on either currently, or very soon, ideally in time for the next release. release-note-none Denotes a PR that doesn't merit a release note. sig/api-machinery Categorizes an issue or PR as relevant to SIG API Machinery. size/M Denotes a PR that changes 30-99 lines, ignoring generated files. triage/accepted Indicates an issue or PR is ready to be actively worked on.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

6 participants