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.

Sign up for GitHub

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

Jump to bottom

TestTokenGeneration flakiness #14979

Closed
rosstimothy opened this issue Jul 28, 2022 · 3 comments · Fixed by #15090
Closed

TestTokenGeneration flakiness #14979

rosstimothy opened this issue Jul 28, 2022 · 3 comments · Fixed by #15090
Assignees
@mcbattirola
Labels
flaky tests

Comments

@rosstimothy
Copy link
Contributor

Failure

Data Race in all TestTokenGeneration subtests

===================================================
OUTPUT github.com/gravitational/teleport/lib/web.TestTokenGeneration/single_app_role
===================================================
=== RUN   TestTokenGeneration/single_app_role
=== PAUSE TestTokenGeneration/single_app_role
=== CONT  TestTokenGeneration/single_app_role
=== CONT  TestTokenGeneration/single_app_role
    testing.go:1312: race detected during execution of test
{"caller":"native/native.go:242","component":"keygen","level":"debug","message":"generated user key for [-teleport-nologin-525e5501-bb10-4e1f-8e6e-56a1e7a3ae0e -teleport-internal-join] with expiry on (1659001666) 2022-07-28 09:47:46.751776411 +0000 UTC","timestamp":"2022-07-27T21:47:52Z"}
{"caller":"auth/auth.go:1154","component":"auth","level":"debug","message":"Failed setting default kubernetes cluster for user login (user did not provide a cluster); leaving KubernetesCluster extension in the TLS certificate empty","timestamp":"2022-07-27T21:47:52Z"}
{"caller":"tlsca/ca.go:873","common_name":"test-user@example.com","component":"ca","dns_names":null,"level":"info","locality":["-teleport-nologin-525e5501-bb10-4e1f-8e6e-56a1e7a3ae0e","-teleport-internal-join"],"message":"Generating TLS certificate {0xc0028887e0 0xc00190b4e0 1.3.9999.1.7=#13096c6f63616c686f7374,CN=test-user@example.com,O=user:test-user@example.com,POSTALCODE=null,STREET=localhost,L=-teleport-nologin-525e5501-bb10-4e1f-8e6e-56a1e7a3ae0e+L=-teleport-internal-join 2022-07-28 09:47:46.751776411 +0000 UTC [] [] 5 []}.","not_after":"2022-07-28T09:47:46.751776411Z","org":["user:test-user@example.com"],"org_unit":[],"timestamp":"2022-07-27T21:47:52Z"}
{"caller":"auth/middleware.go:680","component":"auth","level":"debug","message":"ClientCertPool -\u003e cert(localhost issued by localhost:114114186839476383502693315334450992642)","timestamp":"2022-07-27T21:47:52Z"}
{"caller":"auth/middleware.go:680","component":"auth","level":"debug","message":"ClientCertPool -\u003e cert(localhost issued by localhost:302201449837414720779103897709316011246)","timestamp":"2022-07-27T21:47:52Z"}
{"caller":"auth/middleware.go:317","component":"auth","level":"debug","message":"Server certificate cert(test-tls-server.localhost issued by localhost:114114186839476383502693315334450992642).","timestamp":"2022-07-27T21:47:52Z"}
{"caller":"srv/sess.go:180","component":"session:proxy","level":"debug","message":"Closing Session Registry.","timestamp":"2022-07-27T21:47:52Z"}
{"caller":"srv/heartbeat.go:289","component":"proxy:beat","level":"debug","message":"Heartbeat exited.","timestamp":"2022-07-27T21:47:52Z"}
{"caller":"sshutils/server.go:383","component":"ssh:proxy","level":"debug","message":"Server 127.0.0.1:42411 has closed.","timestamp":"2022-07-27T21:47:52Z"}
{"caller":"services/watcher.go:209","component":"proxy:server","level":"debug","message":"Closed, returning from watch loop.","resource-kind":"proxy","timestamp":"2022-07-27T21:47:52Z"}
{"caller":"srv/heartbeat.go:289","component":"node:beat","level":"debug","message":"Heartbeat exited.","timestamp":"2022-07-27T21:47:52Z"}
{"caller":"reversetunnel/srv.go:389","component":"proxy:server","level":"debug","message":"Closing.","timestamp":"2022-07-27T21:47:52Z"}
{"caller":"auth/grpcserver.go:166","component":"auth:grpc","level":"debug","message":"Failed to receive heartbeat: rpc error: code = Canceled desc = context canceled","timestamp":"2022-07-27T21:47:52Z"}
{"caller":"srv/sess.go:180","component":"session:node","level":"debug","message":"Closing Session Registry.","timestamp":"2022-07-27T21:47:52Z"}
{"caller":"backend/buffer.go:330","component":"buffer","level":"debug","message":"Removing watcher 0xc0027c6a80 via external close.","timestamp":"2022-07-27T21:47:52Z"}
{"caller":"sshutils/server.go:383","component":"ssh:node","level":"debug","message":"Server 127.0.0.1:34311 has closed.","timestamp":"2022-07-27T21:47:52Z"}
{"caller":"backend/buffer.go:330","component":"buffer","level":"debug","message":"Removing watcher 0xc0027c6b40 via external close.","timestamp":"2022-07-27T21:47:52Z"}
{"caller":"backend/buffer.go:330","component":"buffer","level":"debug","message":"Removing watcher 0xc0014d15c0 via external close.","timestamp":"2022-07-27T21:47:52Z"}
{"caller":"backend/buffer.go:330","component":"buffer","level":"debug","message":"Removing watcher 0xc001d24fc0 via external close.","timestamp":"2022-07-27T21:47:52Z"}
{"caller":"backend/buffer.go:330","component":"buffer","level":"debug","message":"Removing watcher 0xc001d24000 via external close.","timestamp":"2022-07-27T21:47:52Z"}
{"caller":"backend/buffer.go:333","component":"buffer","level":"debug","message":"Could not find watcher Watcher(name=auth, prefixes=/locks, capacity=1024, size=0).","timestamp":"2022-07-27T21:47:52Z"}
    --- FAIL: TestTokenGeneration/single_app_role (5.44s)
e":"Supported MAC algorithms: [].","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"native/native.go:212","component":"keygen","level":"debug","message":"Generated SSH host certificate for role Auth with principals: [test-tls-server.localhost test-tls-server localhost 127.0.0.1 ::1].","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"tlsca/ca.go:873","common_name":"test-tls-server.localhost","component":"ca","dns_names":["*.teleport.cluster.local","teleport.cluster.local"],"level":"info","locality":[],"message":"Generating TLS certificate {0xc000eacba0 0xc0008927c0 1.3.9999.1.7=#13096c6f63616c686f7374,CN=test-tls-server.localhost,O=Auth,POSTALCODE=null,STREET= 2032-07-24 21:47:46.751859741 +0000 UTC [*.teleport.cluster.local teleport.cluster.local] [] 5 []}.","not_after":"2032-07-24T21:47:46.751859741Z","org":["Auth"],"org_unit":[],"timestamp":"2022-07-27T21:47:48Z"}
{"caller":"backend/buffer.go:312","component":"buffer","level":"debug","message":"Add Watcher(name=proxy0.localhost, prefixes=/proxies, capacity=8192, size=0).","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"sshutils/server.go:242","component":"ssh:proxy","level":"debug","message":"Supported ciphers: [].","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"sshutils/server.go:252","component":"ssh:proxy","level":"debug","message":"Supported KEX algorithms: [].","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"sshutils/server.go:262","component":"ssh:proxy","level":"debug","message":"Supported MAC algorithms: [].","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"regular/sshserver.go:831","component":null,"level":"info","message":"debug -\u003e starting legacy heartbeat.","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"auth/grpcserver.go:4161","component":"auth","level":"debug","message":"GRPC(SERVER): keep alive 1m0s count: 3.","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"srv/heartbeat.go:163","component":"proxy:beat","level":"debug","message":"Starting Proxy heartbeat with announce period: 1m0s, keep-alive period 5m18.6119254s, poll period: 5s","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"web/assets.go:59","component":"web","level":"info","message":"Using filesystem for serving web assets: ../../webassets/teleport.","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"auth/middleware.go:680","component":"auth","level":"debug","message":"ClientCertPool -\u003e cert(localhost issued by localhost:58866693763883361630771369546261735906)","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"auth/middleware.go:680","component":"auth","level":"debug","message":"ClientCertPool -\u003e cert(localhost issued by localhost:249892312733390105055246093442493278264)","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"auth/middleware.go:317","component":"auth","level":"debug","message":"Server certificate cert(test-tls-server.localhost issued by localhost:58866693763883361630771369546261735906).","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"auth/middleware.go:680","component":"auth","level":"debug","message":"ClientCertPool -\u003e cert(localhost issued by localhost:58866693763883361630771369546261735906)","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"auth/middleware.go:680","component":"auth","level":"debug","message":"ClientCertPool -\u003e cert(localhost issued by localhost:249892312733390105055246093442493278264)","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"auth/middleware.go:317","component":"auth","level":"debug","message":"Server certificate cert(test-tls-server.localhost issued by localhost:58866693763883361630771369546261735906).","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"auth/middleware.go:680","component":"auth","level":"debug","message":"ClientCertPool -\u003e cert(localhost issued by localhost:58866693763883361630771369546261735906)","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"auth/middleware.go:680","component":"auth","level":"debug","message":"ClientCertPool -\u003e cert(localhost issued by localhost:249892312733390105055246093442493278264)","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"auth/middleware.go:317","component":"auth","level":"debug","message":"Server certificate cert(test-tls-server.localhost issued by localhost:58866693763883361630771369546261735906).","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"auth/middleware.go:680","component":"auth","level":"debug","message":"ClientCertPool -\u003e cert(localhost issued by localhost:58866693763883361630771369546261735906)","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"auth/middleware.go:680","component":"auth","level":"debug","message":"ClientCertPool -\u003e cert(localhost issued by localhost:249892312733390105055246093442493278264)","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"auth/middleware.go:317","component":"auth","level":"debug","message":"Server certificate cert(test-tls-server.localhost issued by localhost:58866693763883361630771369546261735906).","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"backend/buffer.go:330","component":"buffer","level":"debug","message":"Removing watcher 0xc0011de540 via external close.","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"web/apiserver.go:269","component":"web","error":"missing port in address","level":"warning","message":"Invalid SSH proxy address \"\", will use default port 3023.","timestamp":"2022-07-27T21:47:48Z"}
{"addr":"127.0.0.1:46507","caller":"sshutils/server.go:299","component":"ssh:proxy","level":"debug","message":"Server start.","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"sshutils/server.go:378","component":"ssh:proxy","level":"debug","message":"Listening on 127.0.0.1:46507.","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"native/native.go:212","component":"keygen","level":"debug","message":"Generated SSH host certificate for role Node with principals: [00000000-0000-0000-0000-000000000000.localhost 00000000-0000-0000-0000-000000000000 localhost.localhost localhost 127.0.0.1 ::1].","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"tlsca/ca.go:873","common_name":"00000000-0000-0000-0000-000000000000.localhost","component":"ca","dns_names":[],"level":"info","locality":[],"message":"Generating TLS certificate {0xc0028887e0 0xc0025864a0 1.3.9999.1.7=#13096c6f63616c686f7374,CN=00000000-0000-0000-0000-000000000000.localhost,O=Node,POSTALCODE=null,STREET= 2032-07-24 21:47:46.751776411 +0000 UTC [] [] 5 []}.","not_after":"2032-07-24T21:47:46.751776411Z","org":["Node"],"org_unit":[],"timestamp":"2022-07-27T21:47:48Z"}
{"caller":"native/native.go:212","component":"keygen","level":"debug","message":"Generated SSH host certificate for role Node with principals: [00000000-0000-0000-0000-000000000000.localhost 00000000-0000-0000-0000-000000000000 localhost.localhost localhost 127.0.0.1 ::1].","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"tlsca/ca.go:873","common_name":"00000000-0000-0000-0000-000000000000.localhost","component":"ca","dns_names":[],"level":"info","locality":[],"message":"Generating TLS certificate {0xc0015568a0 0xc0024ee1c0 1.3.9999.1.7=#13096c6f63616c686f7374,CN=00000000-0000-0000-0000-000000000000.localhost,O=Node,POSTALCODE=null,STREET= 2032-07-24 21:47:46.752055371 +0000 UTC [] [] 5 []}.","not_after":"2032-07-24T21:47:46.752055371Z","org":["Node"],"org_unit":[],"timestamp":"2022-07-27T21:47:48Z"}
{"caller":"native/native.go:212","component":"keygen","level":"debug","message":"Generated SSH host certificate for role Node with principals: [node.localhost node localhost 127.0.0.1 ::1].","timestamp":"2022-07-27T21:47:48Z"}
{"caller":"tlsca/ca.go:873","common_name":"node.localhost","component":"ca","dns_names":[],"level":"info","locality":[],"message":"Generating TLS certificate {0xc0028887e0 0xc000f3e770 1.3.9999.1.7=#13096c6f63616c686f7374,CN=node.localhost,O=Node,POSTALCODE=null,STREET= 2032-07-24 21:47:46.751776411 +0000 UTC [] [] 5 []}.","not_after":"2032-07-24T21:47:46.751776411Z","org":["Node"],"org_unit":[],"timestamp":"2022-07-27T21:47:48Z"}
{"caller":"services/watcher.go:177","component":null,"level":"debug","message":"Starting watch.","resource-
==================
WARNING: DATA RACE
Write at 0x00c001491b80 by goroutine 237:
  github.com/gravitational/teleport/api/types.(*RoleV5).setStaticFields()
      /workspace/api/types/role.go:663 +0x4f
  github.com/gravitational/teleport/api/types.(*RoleV5).CheckAndSetDefaults()
      /workspace/api/types/role.go:671 +0x48
  github.com/gravitational/teleport/lib/services.ValidateRole()
      /workspace/lib/services/role.go:198 +0x5b
  github.com/gravitational/teleport/lib/services.MarshalRole()
      /workspace/lib/services/role.go:2558 +0x73
  github.com/gravitational/teleport/lib/services/local.(*AccessService).UpsertRole()
      /workspace/lib/services/local/access.go:103 +0x97
  github.com/gravitational/teleport/lib/auth.(*Server).UpsertRole()
      /workspace/lib/auth/access.go:31 +0xc1
  github.com/gravitational/teleport/lib/web.(*proxy).createUser()
      /workspace/lib/web/apiserver_test.go:4088 +0x5aa
  github.com/gravitational/teleport/lib/web.(*proxy).authPack()
      /workspace/lib/web/apiserver_test.go:3997 +0x2fe
  github.com/gravitational/teleport/lib/web.TestTokenGeneration.func1()
      /workspace/lib/web/apiserver_test.go:2153 +0x118
  testing.tRunner()
      /opt/go/src/testing/testing.go:1439 +0x213
  testing.(*T).Run.func1()
      /opt/go/src/testing/testing.go:1486 +0x47

Previous write at 0x00c001491b80 by goroutine 65:
  github.com/gravitational/teleport/api/types.(*RoleV5).setStaticFields()
      /workspace/api/types/role.go:663 +0x4d
  github.com/gravitational/teleport/api/types.(*RoleV5).CheckAndSetDefaults()
      /workspace/api/types/role.go:671 +0x48
  github.com/gravitational/teleport/lib/services.ValidateRole()
      /workspace/lib/services/role.go:198 +0x5b
  github.com/gravitational/teleport/lib/services.MarshalRole()
      /workspace/lib/services/role.go:2558 +0x73
  github.com/gravitational/teleport/lib/services/local.(*AccessService).UpsertRole()
      /workspace/lib/services/local/access.go:103 +0x97
  github.com/gravitational/teleport/lib/auth.(*Server).UpsertRole()
      /workspace/lib/auth/access.go:31 +0xc1
  github.com/gravitational/teleport/lib/web.(*proxy).createUser()
      /workspace/lib/web/apiserver_test.go:4088 +0x5aa
  github.com/gravitational/teleport/lib/web.(*proxy).authPack()
      /workspace/lib/web/apiserver_test.go:3997 +0x2fe
  github.com/gravitational/teleport/lib/web.TestTokenGeneration.func1()
      /workspace/lib/web/apiserver_test.go:2153 +0x118
  testing.tRunner()
      /opt/go/src/testing/testing.go:1439 +0x213
  testing.(*T).Run.func1()
      /opt/go/src/testing/testing.go:1486 +0x47

Goroutine 237 (running) created at:
  testing.(*T).Run()
      /opt/go/src/testing/testing.go:1486 +0x724
  github.com/gravitational/teleport/lib/web.TestTokenGeneration()
      /workspace/lib/web/apiserver_test.go:2148 +0x9bc
  testing.tRunner()
      /opt/go/src/testing/testing.go:1439 +0x213
  testing.(*T).Run.func1()
      /opt/go/src/testing/testing.go:1486 +0x47

Goroutine 65 (running) created at:
  testing.(*T).Run()
      /opt/go/src/testing/testing.go:1486 +0x724
  github.com/gravitational/teleport/lib/web.TestTokenGeneration()
      /workspace/lib/web/apiserver_test.go:2148 +0x9bc
  testing.tRunner()
      /opt/go/src/testing/testing.go:1439 +0x213
  testing.(*T).Run.func1()
      /opt/go/src/testing/testing.go:1486 +0x47
==================
==================
WARNING: DATA RACE
Read at 0x00c001491ba0 by goroutine 237:
  github.com/gravitational/teleport/api/types.(*RoleV5).setStaticFields()
      /workspace/api/types/role.go:664 +0x8f
  github.com/gravitational/teleport/api/types.(*RoleV5).CheckAndSetDefaults()
      /workspace/api/types/role.go:671 +0x48
  github.com/gravitational/teleport/lib/services.ValidateRole()
      /workspace/lib/services/role.go:198 +0x5b
  github.com/gravitational/teleport/lib/services.MarshalRole()
      /workspace/lib/services/role.go:2558 +0x73
  github.com/gravitational/teleport/lib/services/local.(*AccessService).UpsertRole()
      /workspace/lib/services/local/access.go:103 +0x97
  github.com/gravitational/teleport/lib/auth.(*Server).UpsertRole()
      /workspace/lib/auth/access.go:31 +0xc1
  github.com/gravitational/teleport/lib/web.(*proxy).createUser()
      /workspace/lib/web/apiserver_test.go:4088 +0x5aa
  github.com/gravitational/teleport/lib/web.(*proxy).authPack()
      /workspace/lib/web/apiserver_test.go:3997 +0x2fe
  github.com/gravitational/teleport/lib/web.TestTokenGeneration.func1()
      /workspace/lib/web/apiserver_test.go:2153 +0x118
  testing.tRunner()
      /opt/go/src/testing/testing.go:1439 +0x213
  testing.(*T).Run.func1()
      /opt/go/src/testing/testing.go:1486 +0x47

Previous write at 0x00c001491ba0 by goroutine 65:
  github.com/gravitational/teleport/api/types.(*RoleV5).setStaticFields()
      /workspace/api/types/role.go:665 +0x1be
  github.com/gravitational/teleport/api/types.(*RoleV5).CheckAndSetDefaults()
      /workspace/api/types/role.go:671 +0x48
  github.com/gravitational/teleport/lib/services.ValidateRole()
      /workspace/lib/services/role.go:198 +0x5b
  github.com/gravitational/teleport/lib/services.MarshalRole()
      /workspace/lib/services/role.go:2558 +0x73
  github.com/gravitational/teleport/lib/services/local.(*AccessService).UpsertRole()
      /workspace/lib/services/local/access.go:103 +0x97
  github.com/gravitational/teleport/lib/auth.(*Server).UpsertRole()
      /workspace/lib/auth/access.go:31 +0xc1
  github.com/gravitational/teleport/lib/web.(*proxy).createUser()
      /workspace/lib/web/apiserver_test.go:4088 +0x5aa
  github.com/gravitational/teleport/lib/web.(*proxy).authPack()
      /workspace/lib/web/apiserver_test.go:3997 +0x2fe
  github.com/gravitational/teleport/lib/web.TestTokenGeneration.func1()
      /workspace/lib/web/apiserver_test.go:2153 +0x118
  testing.tRunner()
      /opt/go/src/testing/testing.go:1439 +0x213
  testing.(*T).Run.func1()
      /opt/go/src/testing/testing.go:1486 +0x47

Goroutine 237 (running) created at:
  testing.(*T).Run()
      /opt/go/src/testing/testing.go:1486 +0x724
  github.com/gravitational/teleport/lib/web.TestTokenGeneration()
      /workspace/lib/web/apiserver_test.go:2148 +0x9bc
  testing.tRunner()
      /opt/go/src/testing/testing.go:1439 +0x213
  testing.(*T).Run.func1()
      /opt/go/src/testing/testing.go:1486 +0x47

Goroutine 65 (running) created at:
  testing.(*T).Run()
      /opt/go/src/testing/testing.go:1486 +0x724
  github.com/gravitational/teleport/lib/web.TestTokenGeneration()
      /workspace/lib/web/apiserver_test.go:2148 +0x9bc
  testing.tRunner()
      /opt/go/src/testing/testing.go:1439 +0x213
  testing.(*T).Run.func1()
      /opt/go/src/testing/testing.go:1486 +0x47
==================
    --- FAIL: TestTokenGeneration/single_node_role (5.09s)
@rosstimothy rosstimothy mentioned this issue Jul 28, 2022
Closed
@zmb3
Copy link
Collaborator

zmb3 commented Jul 29, 2022

@mcbattirola can you take a look at fixing these?

@mcbattirola mcbattirola mentioned this issue Aug 1, 2022
Merged
@ibeckermayer
Copy link
Contributor

@mcbattirola mind backporting the fix to this to v10 when you get a chance? I just got the same failure on a backport to v10:

https://console.cloud.google.com/cloud-build/builds/a3992318-0ad6-4270-a85e-1728f32de4f3?project=ci-account

@mcbattirola
Copy link
Contributor

@mcbattirola mind backporting the fix to this to v10 when you get a chance? I just got the same failure on a backport to v10:

Sure, thanks for letting me know. #16362

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@mcbattirola mcbattirola

Labels
flaky tests
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Fix TestTokenGeneration flakiness gravitational/teleport
4 participants
@zmb3 @mcbattirola @ibeckermayer @rosstimothy