Data race in httptest.Server - pkg/storage/etcd, pkg/registry/generic/etcd

[wojtek-t]

The failure is the following:

WARNING: DATA RACE
Write by goroutine 95:
  sync.raceWrite()
      /tmp/workdir/go/src/sync/race.go:41 +0x2e
  sync.(*WaitGroup).Wait()
      /tmp/workdir/go/src/sync/waitgroup.go:124 +0xf9
  net/http/httptest.(*Server).Close()
      /tmp/workdir/go/src/net/http/httptest/server.go:168 +0x80
  k8s.io/kubernetes/plugin/pkg/auth/authenticator/token/oidc.TestOIDCAuthentication()
      /workspace/kubernetes/_output/local/go/src/k8s.io/kubernetes/plugin/pkg/auth/authenticator/token/oidc/oidc_test.go:395 +0x1fc1
  testing.tRunner()
      /tmp/workdir/go/src/testing/testing.go:456 +0xdc

Previous read by goroutine 142:
  sync.raceRead()
      /tmp/workdir/go/src/sync/race.go:37 +0x2e
  sync.(*WaitGroup).Add()
      /tmp/workdir/go/src/sync/waitgroup.go:66 +0xfa
  net/http/httptest.(*waitGroupHandler).ServeHTTP()
      /tmp/workdir/go/src/net/http/httptest/server.go:198 +0x5c
  net/http.serverHandler.ServeHTTP()
      /tmp/workdir/go/src/net/http/server.go:1862 +0x206
  net/http.(*conn).serve()
      /tmp/workdir/go/src/net/http/server.go:1361 +0x117c

@timothysc @kubernetes/goog-testing @yifan-gu

[wojtek-t]

The failure comes from: TestOIDCAuthentication

[timothysc]

xref: #18917

Same spot I fail on: https://paste.fedoraproject.org/303002/50488092/

[yifan-gu]

cc @yifan-gu

[wojtek-t]

I've just seen the same error in a different test:

Write by goroutine 48:
  sync.raceWrite()
      /tmp/workdir/go/src/sync/race.go:41 +0x2e
  sync.(*WaitGroup).Wait()
      /tmp/workdir/go/src/sync/waitgroup.go:124 +0xf9
  net/http/httptest.(*Server).Close()
      /tmp/workdir/go/src/net/http/httptest/server.go:168 +0x80
  k8s.io/kubernetes/pkg/storage/etcd/testing.(*EtcdTestServer).Terminate()
      /workspace/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/storage/etcd/testing/utils.go:133 +0x138
  k8s.io/kubernetes/pkg/registry/generic/etcd.TestEtcdWatch()
      /workspace/kubernetes/_output/local/go/src/k8s.io/kubernetes/pkg/registry/generic/etcd/etcd_test.go:610 +0xb5f
  testing.tRunner()
      /tmp/workdir/go/src/testing/testing.go:456 +0xdc

Previous read by goroutine 62:
  sync.raceRead()
      /tmp/workdir/go/src/sync/race.go:37 +0x2e
  sync.(*WaitGroup).Add()
      /tmp/workdir/go/src/sync/waitgroup.go:66 +0xfa
  net/http/httptest.(*waitGroupHandler).ServeHTTP()
      /tmp/workdir/go/src/net/http/httptest/server.go:198 +0x5c
  net/http.serverHandler.ServeHTTP()
      /tmp/workdir/go/src/net/http/server.go:1862 +0x206
  net/http.(*conn).serve()

This failure comes from:
pkg/registry/generic/etcd
TestEtcdWatch

So this may not be related to oidc itself, but maybe to httptest.Server

[wojtek-t]

I've also seen exactly the same in pkg/storage/etcd.

[wojtek-t]

One more failure is here:
https://00e9e64bacc0329d30a8c72bf3aacbc7eab2390b5b3326030c-apidata.googleusercontent.com/download/storage/v1_internal/b/kubernetes-jenkins/o/logs%2Fkubernetes-test-go%2F4825%2Fartifacts%2Fjunit_v1,extensions-v1beta1_20151220-020118.stdout?qk=AD5uMEu0agHjHt_eE9SdciXlWznADg9yBAO45jdlu8PjKdUKcgnXwXmKYrvnIR8uoVY7BTxf_dw0R5EmJYq0u82zpS-4Q0Fl81fVmj7roGIV5IRwT3aC_FHdh1cY4tn7237SsAa3Bq5OYZtgxDZlvk7V5Bu0P93ffmizdWf1bF-VN6eCa5GDmcnwrbKvXNtCT5yMAWY7sYae_sQwZNuYdqubAHDs1HFWqfxRHjrgtC_7syVAbfwAI_cp9L3xFUOFSr5UIOFiHabtiIl_3d1_b1hgOWlNIoDFgRfHyx7ElI6Z7HRLwNd9LUjC2uQOCL9NY53ImbG_YwRaHA17pIB3NbM6rOVrQpCd7_tv0xKKu8tCeA-F7hDBJF59nSgTjYjHprJkrOZu2d5CbHpUKizJhldtyxDlx6JvdzFitww8ip6Z2Ld2ERTS0QD-1zwtC9fjokmnFaWC1n6tfHQzYViAuI4oYtbBD7RVe3qJwPquapSUWhjBfx553it42hRs2do4GKALGlpTwfwy5O1f4CaWHVqO4OI73RPoeJfWW6zKm7YjgcqVvNIhmkW_3yk8aohOzLdODvieBE0IzkUdxZD3bAg4-SfXo57ejyrJQg_rujhSRq0-6qvkmr2p2aCuPMmJvgOPUO1lOGmUtYTqFumbLoSdztdvUowT9l1MwAqHXdrQSXDmeUNdKkUqmL7Kg0Bt3NQkucxFjiPQwKJbINiKsRb9mItuXdhUdi6wO_X4Ays94mFvkEL49M259nUZIp47Y6uGUL_5g0IRYx6SVu7oSIy3ORER1r_AJ5u0dReDGe7D2NfYZRfQnCgfja0TBDFyI8-UxpxlY09AJ5p_Vjv6BkvlsfNlX9l9OfcrBHygjpkZi0tNkWOHoO6ZXsQK8_xSE48z5YEWSlUDT8Z_80S6UOPO1CZcUck_s9uOrPHmaxQ-1UQ08Z1J10JR952k5Fju11HHftxP7vam

This is an interesting one - it is from TestWatchPurposefulShutdown, and there we already have rt.Gosched, so this will not help.

[wojtek-t]

I think I have a hypothesis what can be happening here (although, I'm not able to reproduce it locally).
Basically - it seem for me that there is a race in etcdWatcher (it has always been there, but Go 1.5 exposed it to the world).

What I think is happening here is that:

1. when you call Watch() on etcdHelper, it starts a new go-routine calling etcdWatch()
2. however, there is no synchronization in it - so it can happen that it will be started after some time (e.g. after Stop() is called in the test mentioned above)
3. if that happens, we may be calling etcd server, when it is already terminating...

I will prepare a PR fixing it (although unfortunately I'm not able to reproduce it locally, so this will just be a guess...)

[wojtek-t]

I've sent #18956 - although I hope that it will solve most of problems here.

[wojtek-t]

However - my PR will not fix OIDC test - I think that one is unrelated...

[wojtek-t]

It seems that my fix #18956 didn't help...

[wojtek-t]

One more try to fix tests has just been merged #18999 (although I'm still not able to reproduce them locally)

[wojtek-t]

Since TestOIDCAuthentication is a different issue - I'm creating a separate issue for that one.

[wojtek-t]

Unfortunately the second fix also didn't help (it seems that flakes are rare even after the first fix, but they are still present... - I will debug more.

[wojtek-t]

One more attempt is in #19006

[wojtek-t]

@fgrzadkowski - hopefully it was finally fixed in the fourth attempt :)
I will keep it open for some more time to monitor it, but it seems that is finally done now.

[gmarek]

I'll merge #19187 to make this flakes go away.

[gmarek]

If anyone see this happening again please ping this issue.

[davidopp]

@gmarek should we close this since you merged #19187? if so, please close.

[davidopp]

Oh sorry, I see @xiang90 is working on a less hacky solution, as described here
#18928 (comment)

Re-assigning to him.

[davidopp]

But if we think @wojtek-t 's sleep will fix the problem good enough for now, we should lower the priority of this from P0 to P1 or P2...

[xiang90]

@davidopp Right. Agree to de-prioritize it. I will try to get a more robust one next week.

[davidopp]

Thanks, bumped to P2.

[ikehz]

@xiang90 We're prioritizing flakes for the time being. Is this something you'll be able to get to soon, or should we find someone else to work on it?

[xiang90]

@ihmccreery I am in China recently. I can look into this later. But I assume this issue has been fixed by a work around. And go will also fix the root cause soon. This issue is just to make the test shutdown in a more graceful way.

[davidopp]

As @brendandburns mentioned, this might be fixed by #19458

[ikehz]

Reassigning to @davidopp based on #19458.

[timothysc]

iirc the long term fix is in etcd proper.

[brendandburns]

I'm taking this due to #20123 having the fix.

[xiang90]

@timothysc etcd/client does not really manage the transport layer. We generate and pass in the transport in k8s and k8s has full management of the shutdown. We need to change that part if we want a more graceful shutdown.

[brendandburns]

I'm going to close this issue, since I beleive that #20123 fixes the original issue in the title.

@wojtek-t @xiang90 if you want to open a separate issue related to what you are seeing in etcd, please file a separate issue.