8000 [GarbageCollector] Increase log verbosity for Garbage collector tests by caesarxuchao · Pull Request #30316 · kubernetes/kubernetes · GitHub
[go: up one dir, main page]

Skip to content

Conversation

caesarxuchao
Copy link
Contributor
@caesarxuchao caesarxuchao commented Aug 9, 2016

I cannot reproduce the flake of GC locally, see #28713 (comment), so I increased the log verbosity for Garbage collector tests.


This change is Reviewable

@caesarxuchao caesarxuchao added the sig/api-machinery Categorizes an issue or PR as relevant to SIG API Machinery. label Aug 9, 2016
@caesarxuchao caesarxuchao self-assigned this Aug 9, 2016
@k8s-github-robot k8s-github-robot added size/XS Denotes a PR that changes 0-9 lines, ignoring generated files. release-note-label-needed labels Aug 9, 2016
@caesarxuchao
Copy link
Contributor Author

@k8s-bot unit test this, issue #30079

@caesarxuchao caesarxuchao changed the title [WIP][GarbageCollector] Increase log verbosity for Garbage collector tests [GarbageCollector] Increase log verbosity for Garbage collector tests Aug 10, 2016
@caesarxuchao caesarxuchao assigned gmarek and unassigned caesarxuchao Aug 10, 2016
@caesarxuchao
Copy link
Contributor Author

@caesarxuchao
Copy link
Contributor Author

@k8s-bot unit test this, issue #30079

@gmarek
Copy link
Contributor
gmarek commented Aug 10, 2016

On top of RBAC tests there's also a race:

=== RUN   TestOrphaning
==================
WARNING: DATA RACE
Write by goroutine 525:
  k8s.io/kubernetes/pkg/api/unversioned.(*TypeMeta).SetGroupVersionKind()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/api/unversioned/meta.go:54 +0x6d
  k8s.io/kubernetes/pkg/controller/garbagecollector/metaonly.(*MetadataOnlyObject).SetGroupVersionKind()
      <autogenerated>:3 +0x8b
  k8s.io/kubernetes/pkg/controller/garbagecollector.monitorFor.func1()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/controller/garbagecollector/garbagecollector.go:480 +0x1e7
  k8s.io/kubernetes/pkg/controller/garbagecollector.monitorFor.func3()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/controller/garbagecollector/garbagecollector.go:498 +0x85
  k8s.io/kubernetes/pkg/controller/framework.ResourceEventHandlerFuncs.OnUpdate()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/controller/framework/controller.go:176 +0x5b
  k8s.io/kubernetes/pkg/controller/framework.(*ResourceEventHandlerFuncs).OnUpdate()
      <autogenerated>:26 +0xed
  k8s.io/kubernetes/pkg/controller/framework.NewInformer.func1()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/controller/framework/controller.go:242 +0x379
  k8s.io/kubernetes/pkg/client/cache.(*DeltaFIFO).Pop()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/client/cache/delta_fifo.go:420 +0x3f5
  k8s.io/kubernetes/pkg/controller/framework.(*Controller).processLoop()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/controller/framework/controller.go:127 +0x78
  k8s.io/kubernetes/pkg/controller/framework.(*Controller).(k8s.io/kubernetes/pkg/controller/framework.processLoop)-fm()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/controller/framework/controller.go:103 +0x2d
  k8s.io/kubernetes/pkg/util/wait.JitterUntil.func1()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/util/wait/wait.go:84 +0x2a
  k8s.io/kubernetes/pkg/util/wait.JitterUntil()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/util/wait/wait.go:85 +0xc9
  k8s.io/kubernetes/pkg/util/wait.Until()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/util/wait/wait.go:47 +0x50
  k8s.io/kubernetes/pkg/controller/framework.(*Controller).Run()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/controller/framework/controller.go:103 +0x25d

Previous read by goroutine 1354:
  k8s.io/kubernetes/pkg/api/unversioned.(*TypeMeta).GroupVersionKind()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/api/unversioned/meta.go:59 +0x72
  k8s.io/kubernetes/pkg/controller/garbagecollector/metaonly.(*MetadataOnlyObject).GroupVersionKind()
      <autogenerated>:2 +0x7e
  k8s.io/kubernetes/pkg/api/meta.objectAccessor.GetAPIVersion()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/api/meta/meta.go:138 +0x89
  k8s.io/kubernetes/pkg/api/meta.(*objectAccessor).GetAPIVersion()
      <autogenerated>:34 +0xc8
  k8s.io/kubernetes/pkg/controller/garbagecollector.(*Propagator).processEvent()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/controller/garbagecollector/garbagecollector.go:367 +0x63f
  k8s.io/kubernetes/pkg/controller/garbagecollector.(*Propagator).(k8s.io/kubernetes/pkg/controller/garbagecollector.processEvent)-fm()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/controller/garbagecollector/garbagecollector.go:747 +0x2d
  k8s.io/kubernetes/pkg/util/wait.JitterUntil.func1()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/util/wait/wait.go:84 +0x2a
  k8s.io/kubernetes/pkg/util/wait.JitterUntil()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/util/wait/wait.go:85 +0xc9
  k8s.io/kubernetes/pkg/util/wait.Until()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/util/wait/wait.go:47 +0x50

Goroutine 525 (running) created at:
  k8s.io/kubernetes/pkg/controller/garbagecollector.(*GarbageCollector).Run()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/controller/garbagecollector/garbagecollector.go:732 +0x147

Goroutine 1354 (running) created at:
  k8s.io/kubernetes/pkg/controller/garbagecollector.(*GarbageCollector).Run()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/controller/garbagecollector/garbagecollector.go:747 +0x2b4
==================
==================
WARNING: DATA RACE
Write by goroutine 525:
  k8s.io/kubernetes/pkg/api/unversioned.(*TypeMeta).SetGroupVersionKind()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/api/unversioned/meta.go:54 +0x9b
  k8s.io/kubernetes/pkg/controller/garbagecollector/metaonly.(*MetadataOnlyObject).SetGroupVersionKind()
      <autogenerated>:3 +0x8b
  k8s.io/kubernetes/pkg/controller/garbagecollector.monitorFor.func1()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/controller/garbagecollector/garbagecollector.go:480 +0x1e7
  k8s.io/kubernetes/pkg/controller/garbagecollector.monitorFor.func3()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/controller/garbagecollector/garbagecollector.go:498 +0x85
  k8s.io/kubernetes/pkg/controller/framework.ResourceEventHandlerFuncs.OnUpdate()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/controller/framework/controller.go:176 +0x5b
  k8s.io/kubernetes/pkg/controller/framework.(*ResourceEventHandlerFuncs).OnUpdate()
      <autogenerated>:26 +0xed
  k8s.io/kubernetes/pkg/controller/framework.NewInformer.func1()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/controller/framework/controller.go:242 +0x379
  k8s.io/kubernetes/pkg/client/cache.(*DeltaFIFO).Pop()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/client/cache/delta_fifo.go:420 +0x3f5
  k8s.io/kubernetes/pkg/controller/framework.(*Controller).processLoop()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/controller/framework/controller.go:127 +0x78
  k8s.io/kubernetes/pkg/controller/framework.(*Controller).(k8s.io/kubernetes/pkg/controller/framework.processLoop)-fm()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/controller/framework/controller.go:103 +0x2d
  k8s.io/kubernetes/pkg/util/wait.JitterUntil.func1()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/util/wait/wait.go:84 +0x2a
  k8s.io/kubernetes/pkg/util/wait.JitterUntil()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/util/wait/wait.go:85 +0xc9
  k8s.io/kubernetes/pkg/util/wait.Until()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/util/wait/wait.go:47 +0x50
  k8s.io/kubernetes/pkg/controller/framework.(*Controller).Run()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/controller/framework/controller.go:103 +0x25d

Previous read by goroutine 1354:
  k8s.io/kubernetes/pkg/api/unversioned.(*TypeMeta).GroupVersionKind()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/api/unversioned/meta.go:59 +0x83
  k8s.io/kubernetes/pkg/controller/garbagecollector/metaonly.(*MetadataOnlyObject).GroupVersionKind()
      <autogenerated>:2 +0x7e
  k8s.io/kubernetes/pkg/api/meta.objectAccessor.GetAPIVersion()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io
8000
/kubernetes/pkg/api/meta/meta.go:138 +0x89
  k8s.io/kubernetes/pkg/api/meta.(*objectAccessor).GetAPIVersion()
      <autogenerated>:34 +0xc8
  k8s.io/kubernetes/pkg/controller/garbagecollector.(*Propagator).processEvent()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/controller/garbagecollector/garbagecollector.go:367 +0x63f
  k8s.io/kubernetes/pkg/controller/garbagecollector.(*Propagator).(k8s.io/kubernetes/pkg/controller/garbagecollector.processEvent)-fm()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/controller/garbagecollector/garbagecollector.go:747 +0x2d
  k8s.io/kubernetes/pkg/util/wait.JitterUntil.func1()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/util/wait/wait.go:84 +0x2a
  k8s.io/kubernetes/pkg/util/wait.JitterUntil()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/util/wait/wait.go:85 +0xc9
  k8s.io/kubernetes/pkg/util/wait.Until()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/util/wait/wait.go:47 +0x50

Goroutine 525 (running) created at:
  k8s.io/kubernetes/pkg/controller/garbagecollector.(*GarbageCollector).Run()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/controller/garbagecollector/garbagecollector.go:732 +0x147

Goroutine 1354 (running) created at:
  k8s.io/kubernetes/pkg/controller/garbagecollector.(*GarbageCollector).Run()
      /go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/controller/garbagecollector/garbagecollector.go:747 +0x2b4
==================

@caesarxuchao caesarxuchao force-pushed the debug-cascading-deletion branch from 126fee8 to d0ec359 Compare August 10, 2016 17:45
@k8s-github-robot k8s-github-robot added size/S Denotes a PR that changes 10-29 lines, ignoring generated files. and removed size/XS Denotes a PR that changes 0-9 lines, ignoring generated files. labels Aug 10, 2016
@caesarxuchao
Copy link
Contributor Author

The race should be fixed now.

@k8s-bot unit test this, issue #30079

@caesarxuchao
Copy link
Contributor Author

@k8s-bot unit test this, issue #30079

1 similar comment
@caesarxuchao
Copy link
Contributor Author

@k8s-bot unit test this, issue #30079

@caesarxuchao
Copy link
Contributor Author

unit test out of memory.

@k8s-bot unit test this, issue #IGNORE

@caesarxuchao
Copy link
Contributor Author

@k8s-bot unit test this, issue #30079

@caesarxuchao caesarxuchao force-pushed the debug-cascading-deletion branch from d0ec359 to c2e01ee Compare August 11, 2016 03:49
@gmarek
Copy link
Contributor
gmarek commented Aug 11, 2016

GKE test endpoint is down...

setObjectTypeMeta(oldObj)
// oldObj is obtained from the informer's cache, so it should
// have typeMeta set. Setting it again here causes data race.
// setObjectTypeMeta(oldObj)
Copy link
Contributor

Choose a reason for hiding this comment

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

This looks sketchy... @wojtek-t @lavalamp

Copy link
Contributor Author

Choose a reason for hiding this comment

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

@gmarek could you be more specific? Is it the setObjectTypeMeta looking sketchy or not setting typemeta for oldObj sketchy? For the former, I've convince @lavalamp there is no better way in #28480 (comment). For the latter, the oldObj is not even used by the GC, so it's safe.

Copy link
Contributor

Choose a reason for hiding this comment

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

The fact that this causes race is surprising. The fact that the same method for newObj doesn't is even more surprising.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

It's because the oldObj is get from the controller cache (https://github.com/kubernetes/kubernetes/blob/master/pkg/controller/framework/controller.go#L238), so garbage collector's processEvent may be processing the object already. The newObj is obtained through list or watch and is fresh, so it's not causing race.

Copy link
Contributor

Choose a reason for hiding this comment

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

Sorry I didn't catch this in review. We can't modify objects coming from a shared informer cache. I thought this wasn't a shared informer cache though. Where is the code that this races with?

Copy link
Contributor

Choose a reason for hiding this comment

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

So what's the verdict on this. I take it it's unneeded since it's already been set, but is it actually fixing a 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.

Because we increase the log level, the log function will read the data and causes the race. We need this fix.

Copy link
Contributor

Choose a reason for hiding this comment

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

Can you delete the line instead of commenting the line out?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

ok.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Done.

@gmarek
Copy link
Contributor
gmarek commented Aug 11, 2016

The Informer thing looks rather sketchy to me. I asked @wojtek-t and he also thinks it's suspicious. @lavalamp can you please take a look?

@k8s-github-robot k8s-github-robot added the needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. label Aug 11, 2016
@gmarek
Copy link
Contributor
gmarek commented Aug 18, 2016

Adding @lavalamp to give final LGTM if the informer thing is correct.

@k8s-github-robot k8s-github-robot removed the needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. label Aug 26, 2016
@caesarxuchao
Copy link
Contributor Author

@lavalamp I still want to merge this. The issue this PR intends to debug is #28713, it's marked with flake-needs-czar-attention-release-1.4 label, though the last occurrence was 14 days ago.

@caesarxuchao caesarxuchao force-pushed the debug-cascading-deletion branch from e125fc0 to 9ac91e5 Compare August 26, 2016 22:58
@k8s-github-robot k8s-github-robot added size/XS Denotes a PR that changes 0-9 lines, ignoring generated files. and removed size/S Denotes a PR that changes 10-29 lines, ignoring generated files. labels 6D38 Aug 26, 2016
@k8s-bot
Copy link
k8s-bot commented Aug 26, 2016

GCE e2e build/test passed for commit 9ac91e5.

@lavalamp lavalamp added release-note-none Denotes a PR that doesn't merit a release note. lgtm "Looks good to me", indicates that a PR is ready to be merged. labels Aug 26, 2016
@lavalamp lavalamp added this to the v1.4 milestone Aug 26, 2016
gc.propagator.eventQueue.Add(&workqueue.TimedWorkQueueItem{StartTime: gc.clock.Now(), Object: event})
},
UpdateFunc: func(oldObj, newObj interface{}) {
setObjectTypeMeta(newObj)
Copy link
Contributor

Choose a reason for hiding this comment

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

Can you open an issue so we'll revisit whether it's OK for garbage collector to mutate these objects?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

@k8s-github-robot
Copy link

Automatic merge from submit-queue

@k8s-github-robot k8s-github-robot merged commit 60f978d into kubernetes:master Aug 27, 2016
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

lgtm "Looks good to me", indicates that a PR is ready to be merged. 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/XS Denotes a PR that changes 0-9 lines, ignoring generated files.

Projects

None yet

Development

Successfully merging this pull request may close these issues.

6 participants

0