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

TestPeriodicCheck race detected during execution of test #17317

Closed
tjungblu opened this issue Jan 24, 2024 · 3 comments · Fixed by #17365
Closed

TestPeriodicCheck race detected during execution of test #17317

tjungblu opened this issue Jan 24, 2024 · 3 comments · Fixed by #17365
Assignees
@fuweid
Labels
area/testing help wanted type/flake

Comments

@tjungblu
Copy link
Contributor

Which github workflows are flaking?

pull-etcd-unit-test

Which tests are flaking?

TestPeriodicCheck

Github Action link

https://prow.k8s.io/view/gs/kubernetes-jenkins/pr-logs/pull/etcd-io_etcd/17307/pull-etcd-unit-test/1750174108529725440

Reason for failure (if possible)

{Failed  === RUN   TestPeriodicCheck
    testing.go:1465: race detected during execution of test
--- FAIL: TestPeriodicCheck (0.01s)
=== RUN   TestPeriodicCheck/Same_local_hash_and_no_peers
    logger.go:130: 2024-01-24T15:12:26.125Z	INFO	finished peer corruption check	{"number-of-peers-checked": 0}
    --- PASS: TestPeriodicCheck/Same_local_hash_and_no_peers (0.00s)
=== RUN   TestPeriodicCheck/Error_getting_hash_first_time
    --- PASS: TestPeriodicCheck/Error_getting_hash_first_time (0.00s)
=== RUN   TestPeriodicCheck/Error_getting_hash_second_time
    --- PASS: TestPeriodicCheck/Error_getting_hash_second_time (0.00s)
=== RUN   TestPeriodicCheck/Error_linearizableReadNotify
    --- PASS: TestPeriodicCheck/Error_linearizableReadNotify (0.00s)
=== RUN   TestPeriodicCheck/Different_local_hash_and_revision
    logger.go:130: 2024-01-24T15:12:26.126Z	INFO	finished peer corruption check	{"number-of-peers-checked": 0}
    --- PASS: TestPeriodicCheck/Different_local_hash_and_revision (0.00s)
=== RUN   TestPeriodicCheck/Different_local_hash_and_compaction_revision
    logger.go:130: 2024-01-24T15:12:26.127Z	INFO	finished peer corruption check	{"number-of-peers-checked": 0}
    --- PASS: TestPeriodicCheck/Different_local_hash_and_compaction_revision (0.00s)
=== RUN   TestPeriodicCheck/Different_local_hash_and_same_revisions
==================
WARNING: DATA RACE
Read at 0x00c0004aba43 by goroutine 132:
  testing.(*common).logDepth()
      /usr/local/go/src/testing/testing.go:1017 +0x504
  testing.(*common).log()
      /usr/local/go/src/testing/testing.go:1004 +0xa4
  testing.(*common).Logf()
      /usr/local/go/src/testing/testing.go:1055 +0x6a
  testing.(*T).Logf()
      <autogenerated>:1 +0x69
  go.uber.org/zap/zaptest.testingWriter.Write()
      /home/prow/go/pkg/mod/go.uber.org/zap@v1.26.0/zaptest/logger.go:130 +0x11d
  go.uber.org/zap/zaptest.(*testingWriter).Write()
      <autogenerated>:1 +0x74
  go.uber.org/zap/zapcore.(*ioCore).Write()
      /home/prow/go/pkg/mod/go.uber.org/zap@v1.26.0/zapcore/core.go:99 +0x192
  go.uber.org/zap/zapcore.(*CheckedEntry).Write()
      /home/prow/go/pkg/mod/go.uber.org/zap@v1.26.0/zapcore/entry.go:253 +0x2ef
  go.uber.org/zap.(*SugaredLogger).log()
      /home/prow/go/pkg/mod/go.uber.org/zap@v1.26.0/sugar.go:316 +0x12f
  go.uber.org/zap.(*SugaredLogger).Debugf()
      /home/prow/go/pkg/mod/go.uber.org/zap@v1.26.0/sugar.go:171 +0x97
  go.etcd.io/etcd/server/v3/storage/backend.(*zapBoltLogger).Debugf()
      <autogenerated>:1 +0x1f
  go.etcd.io/bbolt.(*Tx).Commit()
      /home/prow/go/pkg/mod/go.etcd.io/bbolt@v1.4.0-alpha.0/tx.go:173 +0x205
  go.etcd.io/etcd/server/v3/storage/backend.(*batchTx).commit()
      /home/prow/go/src/github.com/etcd-io/etcd/server/storage/backend/batch_tx.go:269 +0xde
  go.etcd.io/etcd/server/v3/storage/backend.(*batchTxBuffered).unsafeCommit()
      /home/prow/go/src/github.com/etcd-io/etcd/server/storage/backend/batch_tx.go:378 +0x424
  go.etcd.io/etcd/server/v3/storage/backend.(*batchTxBuffered).commit()
      /home/prow/go/src/github.com/etcd-io/etcd/server/storage/backend/batch_tx.go:355 +0x77
  go.etcd.io/etcd/server/v3/storage/backend.(*batchTxBuffered).Commit()
      /home/prow/go/src/github.com/etcd-io/etcd/server/storage/backend/batch_tx.go:342 +0x34
  go.etcd.io/etcd/server/v3/storage/backend.(*backend).run()
      /home/prow/go/src/github.com/etcd-io/etcd/server/storage/backend/backend.go:426 +0x2c6
  go.etcd.io/etcd/server/v3/storage/backend.newBackend.func1()
      /home/prow/go/src/github.com/etcd-io/etcd/server/storage/backend/backend.go:227 +0x33

Previous write at 0x00c0004aba43 by goroutine 129:
  testing.tRunner.func1()
      /usr/local/go/src/testing/testing.go:1582 +0x8fa
  runtime.deferreturn()
      /usr/local/go/src/runtime/panic.go:477 +0x30
  testing.(*T).Run.func1()
      /usr/local/go/src/testing/testing.go:1648 +0x44

Goroutine 132 (running) created at:
  go.etcd.io/etcd/server/v3/storage/backend.newBackend()
      /home/prow/go/src/github.com/etcd-io/etcd/server/storage/backend/backend.go:227 +0xbfc
  go.etcd.io/etcd/server/v3/storage/backend.New()
      /home/prow/go/src/github.com/etcd-io/etcd/server/storage/backend/backend.go:164 +0x457
  go.etcd.io/etcd/server/v3/storage.newBackend()
      /home/prow/go/src/github.com/etcd-io/etcd/server/storage/backend.go:55 +0x460
  go.etcd.io/etcd/server/v3/storage.OpenBackend.func1()
      /home/prow/go/src/github.com/etcd-io/etcd/server/storage/backend.go:76 +0xf3

Goroutine 129 (finished) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:1648 +0x845
  testing.runTests.func1()
      /usr/local/go/src/testing/testing.go:2054 +0x84
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1595 +0x261
  testing.runTests()
      /usr/local/go/src/testing/testing.go:2052 +0x8ad
  testing.(*M).Run()
      /usr/local/go/src/testing/testing.go:1925 +0xcd7
  main.main()
      _testmain.go:133 +0x2bd
==================
    logger.go:130: 2024-01-24T15:12:26.131Z	WARN	found hash mismatch	{"revision-1": 1, "compact-revision-1": 1, "hash-1": 1, "revision-2": 1, "compact-revision-2": 1, "hash-2": 2}
    logger.go:130: 2024-01-24T15:12:26.132Z	INFO	finished peer corruption check	{"number-of-peers-checked": 0}
    --- PASS: TestPeriodicCheck/Different_local_hash_and_same_revisions (0.00s)
=== RUN   TestPeriodicCheck/Peer_with_nil_response
    logger.go:130: 2024-01-24T15:12:26.133Z	INFO	finished peer corruption check	{"number-of-peers-checked": 0}
    --- PASS: TestPeriodicCheck/Peer_with_nil_response (0.00s)
=== RUN   TestPeriodicCheck/Peer_with_newer_revision
    logger.go:130: 2024-01-24T15:12:26.133Z	WARN	revision from follower must be less than or equal to leader's	{"leader-revision": 0, "follower-revision": 1, "follower-peer-id": "2a"}
    logger.go:130: 2024-01-24T15:12:26.133Z	INFO	finished peer corruption check	{"number-of-peers-checked": 1}
    --- PASS: TestPeriodicCheck/Peer_with_newer_revision (0.00s)
=== RUN   TestPeriodicCheck/Peer_with_newer_compact_revision
    logger.go:130: 2024-01-24T15:12:26.134Z	WARN	revision from follower must be less than or equal to leader's	{"leader-revision": 0, "follower-revision": 10, "follower-peer-id": "58"}
    logger.go:130: 2024-01-24T15:12:26.134Z	WARN	compact revision from follower must be less than or equal to leader's	{"leader-compact-revision": 0, "follower-compact-revision": 2, "follower-peer-id": "58"}
    logger.go:130: 2024-01-24T15:12:26.134Z	INFO	finished peer corruption check	{"number-of-peers-checked": 1}
    --- PASS: TestPeriodicCheck/Peer_with_newer_compact_revision (0.00s)
=== RUN   TestPeriodicCheck/Peer_with_same_hash_and_compact_revision
    logger.go:130: 2024-01-24T15:12:26.134Z	INFO	finished peer corruption check	{"number-of-peers-checked": 1}
    --- PASS: TestPeriodicCheck/Peer_with_same_hash_and_compact_revision (0.00s)
=== RUN   TestPeriodicCheck/Peer_with_different_hash_and_same_compact_revision_as_first_local
    logger.go:130: 2024-01-24T15:12:26.135Z	WARN	same compact revision then hashes must match	{"leader-compact-revision": 2, "leader-hash": 1, "follower-compact-revision": 1, "follower-hash": 2, "follower-peer-id": "29a"}
    logger.go:130: 2024-01-24T15:12:26.135Z	INFO	finished peer corruption check	{"number-of-peers-checked": 1}
    --- PASS: TestPeriodicCheck/Peer_with_different_hash_and_same_compact_revision_as_first_local (0.00s)
=== RUN   TestPeriodicCheck/Multiple_corrupted_peers_trigger_one_alarm
    logger.go:130: 2024-01-24T15:12:26.135Z	WARN	revision from follower must be less than or equal to leader's	{"leader-revision": 0, "follower-revision": 10, "follower-peer-id": "58"}
    logger.go:130: 2024-01-24T15:12:26.135Z	WARN	compact revision from follower must be less than or equal to leader's	{"leader-compact-revision": 0, "follower-compact-revision": 2, "follower-peer-id": "58"}
    logger.go:130: 2024-01-24T15:12:26.136Z	WARN	revision from follower must be less than or equal to leader's	{"leader-revision": 0, "follower-revision": 10, "follower-peer-id": "59"}
    logger.go:130: 2024-01-24T15:12:26.136Z	WARN	compact revision from follower must be less than or equal to leader's	{"leader-compact-revision": 0, "follower-compact-revision": 2, "follower-peer-id": "59"}
    logger.go:130: 2024-01-24T15:12:26.136Z	INFO	finished peer corruption check	{"number-of-peers-checked": 2}
    --- PASS: TestPeriodicCheck/Multiple_corrupted_peers_trigger_one_alarm (0.00s)
=== RUN   TestPeriodicCheck/Cluster_ID_Mismatch_does_not_fail_CorruptionChecker.PeriodicCheck()
    logger.go:130: 2024-01-24T15:12:26.136Z	INFO	finished peer corruption check	{"number-of-peers-checked": 0}
    --- PASS: TestPeriodicCheck/Cluster_ID_Mismatch_does_not_fail_CorruptionChecker.PeriodicCheck() (0.00s)
}

Anything else we need to know?

No response
@tjungblu tjungblu mentioned this issue Jan 24, 2024
Merged
@fuweid
Copy link
Member

fuweid commented Jan 26, 2024

/assign

@fuweid fuweid mentioned this issue Feb 4, 2024
Merged
@ahrtr ahrtr reopened this Feb 5, 2024
@ahrtr
Copy link
Member

ahrtr commented Feb 5, 2024

Reopen to track the effort of backporting.

This was referenced Feb 6, 2024
Merged
Merged
@ahrtr
Copy link
Member

ahrtr commented Feb 6, 2024

All done. Thanks @fuweid

@ahrtr ahrtr closed this as completed Feb 6, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@fuweid fuweid

Labels
area/testing help wanted type/flake
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

etcdserver: drain leaky goroutines before test completed fuweid/etcd
4 participants
@serathius @fuweid @ahrtr @tjungblu