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

kv/kvnemesis: TestKVNemesisMultiNode failed #109222

Closed
cockroach-teamcity opened this issue Aug 22, 2023 · 2 comments · Fixed by #109610
Closed

kv/kvnemesis: TestKVNemesisMultiNode failed #109222

cockroach-teamcity opened this issue Aug 22, 2023 · 2 comments · Fixed by #109610
Assignees
Labels
A-testing Testing tools and infrastructure branch-release-22.2 Used to mark GA and release blockers, technical advisories, and bugs for 22.2 C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. T-kv KV Team
Milestone

Comments

@cockroach-teamcity
Copy link
Member

cockroach-teamcity commented Aug 22, 2023

kv/kvnemesis.TestKVNemesisMultiNode failed with artifacts on release-22.2 @ 42fa1fad9af04139575e4f374a8b3f2d4ca453b1:

          |   | 	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store_send.go:205
          |   | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Stores).SendWithWriteBytes
          |   | 	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/stores.go:203
          |   | github.com/cockroachdb/cockroach/pkg/server.(*Node).batchInternal
          |   | 	github.com/cockroachdb/cockroach/pkg/server/node.go:1108
          |   | github.com/cockroachdb/cockroach/pkg/server.(*Node).Batch
          |   | 	github.com/cockroachdb/cockroach/pkg/server/node.go:1161
          |   | github.com/cockroachdb/cockroach/pkg/roachpb._Internal_Batch_Handler.func1
          |   | 	github.com/cockroachdb/cockroach/pkg/roachpb/bazel-out/k8-fastbuild/bin/pkg/roachpb/roachpb_go_proto_/github.com/cockroachdb/cockroach/pkg/roachpb/api.pb.go:9619
          |   | github.com/cockroachdb/cockroach/pkg/util/tracing/grpcinterceptor.ServerInterceptor.func1
          |   | 	github.com/cockroachdb/cockroach/pkg/util/tracing/grpcinterceptor/grpc_interceptor.go:97
          |   | google.golang.org/grpc.chainUnaryInterceptors.func1.1
          |   | 	google.golang.org/grpc/external/org_golang_google_grpc/server.go:1117
          |   | github.com/cockroachdb/cockroach/pkg/rpc.NewServerEx.func3
          |   | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:263
          |   | google.golang.org/grpc.chainUnaryInterceptors.func1.1
          |   | 	google.golang.org/grpc/external/org_golang_google_grpc/server.go:1120
          |   | github.com/cockroachdb/cockroach/pkg/rpc.kvAuth.unaryInterceptor
          |   | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/auth.go:73
          |   | google.golang.org/grpc.chainUnaryInterceptors.func1.1
          |   | 	google.golang.org/grpc/external/org_golang_google_grpc/server.go:1120
          |   | github.com/cockroachdb/cockroach/pkg/rpc.NewServerEx.func1.1
          |   | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:232
          |   | github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunTaskWithErr
          |   | 	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:341
          |   | github.com/cockroachdb/cockroach/pkg/rpc.NewServerEx.func1
          |   | 	github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:230
          |   | google.golang.org/grpc.chainUnaryInterceptors.func1.1
          |   | 	google.golang.org/grpc/external/org_golang_google_grpc/server.go:1120
          |   | google.golang.org/grpc.chainUnaryInterceptors.func1
          |   | 	google.golang.org/grpc/external/org_golang_google_grpc/server.go:1122
          |   | github.com/cockroachdb/cockroach/pkg/roachpb._Internal_Batch_Handler
          |   | 	github.com/cockroachdb/cockroach/pkg/roachpb/bazel-out/k8-fastbuild/bin/pkg/roachpb/roachpb_go_proto_/github.com/cockroachdb/cockroach/pkg/roachpb/api.pb.go:9621
          |   | google.golang.org/grpc.(*Server).processUnaryRPC
          |   | 	google.golang.org/grpc/external/org_golang_google_grpc/server.go:1283
          |   | google.golang.org/grpc.(*Server).handleStream
          |   | 	google.golang.org/grpc/external/org_golang_google_grpc/server.go:1620
          |   | google.golang.org/grpc.(*Server).serveStreams.func1.2
          |   | 	google.golang.org/grpc/external/org_golang_google_grpc/server.go:922
          |   | runtime.goexit
          |   | 	GOROOT/src/runtime/asm_amd64.s:1594
          | Wraps: (2) waiting for all right-hand replicas to initialize
          | Wraps: (3) operation "wait for replicas init" timed out after 5.001s (given timeout 5s)
          | Wraps: (4) rpc error: code = DeadlineExceeded desc = context deadline exceeded
          | Error types: (1) *errbase.opaqueWrapper (2) *errutil.withPrefix (3) *contextutil.TimeoutError (4) *status.Error
        Wraps: (7) merge failed: waiting for all right-hand replicas to initialize: operation "wait for replicas init" timed out after 5.001s (given timeout 5s): rpc error: code = DeadlineExceeded desc = context deadline exceeded
        Error types: (1) *withstack.withStack (2) *errutil.withPrefix (3) *errbase.opaqueWrapper (4) *errutil.withPrefix (5) *errbase.opaqueWrapper (6) *secondary.withSecondaryError (7) *errutil.leafError
    kvnemesis_test.go:113: -- test log scope end --
test logs left over in: /artifacts/tmp/_tmp/1f42cf5be2fc021646bf9b2daf5eaef3/logTestKVNemesisMultiNode620433359
--- FAIL: TestKVNemesisMultiNode (20.09s)

Parameters: TAGS=bazel,gss

Help

See also: How To Investigate a Go Test Failure (internal)

/cc @cockroachdb/kv

This test on roachdash | Improve this report!

Jira issue: CRDB-30833

@cockroach-teamcity cockroach-teamcity added branch-release-22.2 Used to mark GA and release blockers, technical advisories, and bugs for 22.2 C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. T-kv KV Team labels Aug 22, 2023
@cockroach-teamcity cockroach-teamcity added this to the 22.2 milestone Aug 22, 2023
@kvoli
Copy link
Collaborator

kvoli commented Aug 24, 2023

wait for replicas init" timed out after 5.001s (given timeout 5s) merge fails. Seems like a timing issue with the test.

@kvoli kvoli added C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. A-testing Testing tools and infrastructure labels Aug 24, 2023
@mgartner
Copy link
Collaborator

I saw this fail in CI here: https://teamcity.cockroachdb.com/buildConfiguration/Cockroach_BazelEssentialCi/11522338?hideProblemsFromDependencies=false&hideTestsFromDependencies=false&expandBuildChangesSection=true&expandBuildProblemsSection=true&expandBuildTestsSection=true

panic: only transactional requests can acquire exclusive locks [recovered]
  panic: only transactional requests can acquire exclusive locks [recovered]
  panic: only transactional requests can acquire exclusive locks
goroutine 23042 [running]:
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).recover(0xc00159dea0?, {0x6aead88, 0xc00581ac30})
  github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:230 +0x6a
panic({0x477b600, 0xc00c9eac30})
  GOROOT/src/runtime/panic.go:884 +0x212
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).SendWithWriteBytes.func1()
  github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store_send.go:109 +0x152
panic({0x477b600, 0xc00c9eac30})
  GOROOT/src/runtime/panic.go:890 +0x262
github.com/cockroachdb/cockroach/pkg/kv/kvserver/concurrency.assert(...)
  github.com/cockroachdb/cockroach/pkg/kv/kvserver/concurrency/lock_table.go:3994
github.com/cockroachdb/cockroach/pkg/kv/kvserver/concurrency.makeLockMode(0xe1bba40?, 0xc00e3b4280?, {0x3?, 0xebc2a562?, 0x39?})
  github.com/cockroachdb/cockroach/pkg/kv/kvserver/concurrency/lock_table.go:815 +0x11e
github.com/cockroachdb/cockroach/pkg/kv/kvserver/concurrency.(*lockTableGuardImpl).IsKeyLockedByConflictingTxn(0xc00e3b4280, {0xc0098d72c0, 0x14, 0xc00ab5c930?}, 0x3)
  github.com/cockroachdb/cockroach/pkg/kv/kvserver/concurrency/lock_table.go:713 +0x6cf
github.com/cockroachdb/cockroach/pkg/kv/kvserver/concurrency.(*Guard).IsKeyLockedByConflictingTxn(0xc0098d72c0?, {0xc0098d72c0?, 0xc0098d66c0?, 0xf?}, 0x0?)
  github.com/cockroachdb/cockroach/pkg/kv/kvserver/concurrency/concurrency_manager.go:787 +0x2d
github.com/cockroachdb/cockroach/pkg/storage.(*pebbleMVCCScanner).isKeyLockedByConflictingTxn(0xc00a378c00, {0x6aead88, 0xc00581b020}, {0xc0098d72c0?, 0xf?, 0x17?})
  github.com/cockroachdb/cockroach/pkg/storage/pebble_mvcc_scanner.go:1812 +0xc3
github.com/cockroachdb/cockroach/pkg/storage.(*pebbleMVCCScanner).add(0xc00a378c00, {0x6aead88, 0xc00581b020}, {0xc0098d72c0, 0x14, 0x30}, {0xc0098d72c0, 0x1e, 0x30}, {0x7f3a1469918a, ...})
  github.com/cockroachdb/cockroach/pkg/storage/pebble_mvcc_scanner.go:1237 +0xd2
github.com/cockroachdb/cockroach/pkg/storage.(*pebbleMVCCScanner).getOne(0xc00a378c00, {0x6aead88, 0xc00581b020})
  github.com/cockroachdb/cockroach/pkg/storage/pebble_mvcc_scanner.go:828 +0xdb3
github.com/cockroachdb/cockroach/pkg/storage.(*pebbleMVCCScanner).scan(0xc00a378c00, {0x6aead88, 0xc00581b020})
  github.com/cockroachdb/cockroach/pkg/storage/pebble_mvcc_scanner.go:659 +0xc8
github.com/cockroachdb/cockroach/pkg/storage.mvccScanToBytes({_, _}, {_, _}, {_, _, _}, {0xc00611e300, 0x14, 0x18}, ...)
  github.com/cockroachdb/cockroach/pkg/storage/mvcc.go:3874 +0x370
github.com/cockroachdb/cockroach/pkg/storage.mvccScanToKvs({_, _}, {_, _}, {_, _, _}, {0xc00611e300, 0x14, 0x18}, ...)
  github.com/cockroachdb/cockroach/pkg/storage/mvcc.go:3927 +0x125
github.com/cockroachdb/cockroach/pkg/storage.MVCCScan({_, _}, {_, _}, {_, _, _}, {0xc00611e300, 0x14, 0x18}, ...)
  github.com/cockroachdb/cockroach/pkg/storage/mvcc.go:4150 +0x306
github.com/cockroachdb/cockroach/pkg/kv/kvserver/batcheval.ReverseScan({_, _}, {_, _}, {{0x6b6e260, 0xc009a2c738}, {{0x177f927c9ae20233, 0x0, 0x0}, 0xc0057ea670, ...}, ...}, ...)
  github.com/cockroachdb/cockroach/pkg/kv/kvserver/batcheval/cmd_reverse_scan.go:82 +0x919
github.com/cockroachdb/cockroach/pkg/kv/kvserver.evaluateCommand({_, _}, {_, _}, {_, _}, _, _, {{0x177f927c9ae20233, 0x0, ...}, ...}, ...)
  github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_evaluate.go:484 +0x389
github.com/cockroachdb/cockroach/pkg/kv/kvserver.evaluateBatch({_, _}, {_, _}, {_, _}, {_, _}, _, 0xc007bb7e60, ...)
  github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_evaluate.go:303 +0x103e
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).executeReadOnlyBatchWithServersideRefreshes(_, {_, _}, {_, _}, {_, _}, _, _, 0xc00ab60e00, ...)
  github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_read.go:458 +0x413
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).executeReadOnlyBatch(0xc00a0aa580, {0x6aead88, 0xc00581b020}, 0xc007bb7e60, 0xc00b966780)
  github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_read.go:125 +0x725
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).executeBatchWithConcurrencyRetries(0xc00a0aa580, {0x6aead88, 0xc00581b020}, 0xc007bb7e60, 0x5383af0)
  github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_send.go:510 +0x383
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).SendWithWriteBytes(0xc00a0aa580, {0x6aead88?, 0xc00581aea0?}, 0xc007bb7e60)
  github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_send.go:185 +0x6f1
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Store).SendWithWriteBytes(0xc002e76000, {0x6aead88?, 0xc00581ade0?}, 0xc007bb7e60)
  github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/store_send.go:193 +0x66a
github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Stores).SendWithWriteBytes(0x1?, {0x6aead88, 0xc00581ade0}, 0xc007bb7e60)
  github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/stores.go:202 +0xef
github.com/cockroachdb/cockroach/pkg/server.(*Node).batchInternal(0xc001f51000, {0x6aead88?, 0xc00581ad50?}, {0xc005ad1200?}, 0xc007bb7e60)
  github.com/cockroachdb/cockroach/pkg/server/node.go:1336 +0x4b6
github.com/cockroachdb/cockroach/pkg/server.(*Node).Batch(0xc001f51000, {0x6aead88, 0xc00581ac30}, 0xc007bb7e60)
  github.com/cockroachdb/cockroach/pkg/server/node.go:1467 +0x2f5
github.com/cockroachdb/cockroach/pkg/kv/kvpb._Internal_Batch_Handler.func1({0x6aead88, 0xc00581ac30}, {0x4fc31e0?, 0xc007bb7e60})
  github.com/cockroachdb/cockroach/pkg/kv/kvpb/bazel-out/k8-fastbuild/bin/pkg/kv/kvpb/kvpb_go_proto_/github.com/cockroachdb/cockroach/pkg/kv/kvpb/api.pb.go:10290 +0x78
github.com/cockroachdb/cockroach/pkg/util/tracing/grpcinterceptor.ServerInterceptor.func1({0x6aead88, 0xc00581ac30}, {0x4fc31e0, 0xc007bb7e60}, 0xc0069b41e0, 0xc008367878)
  github.com/cockroachdb/cockroach/pkg/util/tracing/grpcinterceptor/grpc_interceptor.go:97 +0x254
google.golang.org/grpc.getChainUnaryHandler.func1({0x6aead88, 0xc00581ac30}, {0x4fc31e0, 0xc007bb7e60})
  google.golang.org/grpc/external/org_golang_google_grpc/server.go:1163 +0xb9
github.com/cockroachdb/cockroach/pkg/rpc.NewServerEx.func3({0x6aead88, 0xc00581ac30}, {0x4fc31e0, 0xc007bb7e60}, 0xc0069b41e0?, 0xc0036111c0)
  github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:169 +0x83
google.golang.org/grpc.getChainUnaryHandler.func1({0x6aead88, 0xc00581ac30}, {0x4fc31e0, 0xc007bb7e60})
  google.golang.org/grpc/external/org_golang_google_grpc/server.go:1163 +0xb9
github.com/cockroachdb/cockroach/pkg/rpc.kvAuth.unaryInterceptor({0xc0023d0000?, {{0x439307?}, {0x6b22530?, 0xc006de0030?}}}, {0x6aead88, 0xc00581ac30}, {0x4fc31e0, 0xc007bb7e60}, 0xc0069b41e0, 0xc003611140)
  github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/auth.go:105 +0x2b4
google.golang.org/grpc.getChainUnaryHandler.func1({0x6aead88, 0xc00581ac30}, {0x4fc31e0, 0xc007bb7e60})
  google.golang.org/grpc/external/org_golang_google_grpc/server.go:1163 +0xb9
github.com/cockroachdb/cockroach/pkg/rpc.NewServerEx.func1.1({0x6aead88?, 0xc00581ac30?})
  github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:136 +0x39
github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunTaskWithErr(0xc0033061e0, {0x6aead88, 0xc00581ac30}, {0x27c?, 0xc00ab63950?}, 0xc00ab63948)
  github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:336 +0xd1
github.com/cockroachdb/cockroach/pkg/rpc.NewServerEx.func1({0x6aead88?, 0xc00581ac30?}, {0x4fc31e0?, 0xc007bb7e60?}, 0xc0069b41e0?, 0xc008367878?)
  github.com/cockroachdb/cockroach/pkg/rpc/pkg/rpc/context.go:134 +0x95
google.golang.org/grpc.chainUnaryInterceptors.func1({0x6aead88, 0xc00581ac30}, {0x4fc31e0, 0xc007bb7e60}, 0xc00db9da20?, 0x49118a0?)
  google.golang.org/grpc/external/org_golang_google_grpc/server.go:1154 +0x8f
github.com/cockroachdb/cockroach/pkg/kv/kvpb._Internal_Batch_Handler({0x4fa2980?, 0xc001f51000}, {0x6aead88, 0xc00581ac30}, 0xc00155d030, 0xc0039a6b00)
  github.com/cockroachdb/cockroach/pkg/kv/kvpb/bazel-out/k8-fastbuild/bin/pkg/kv/kvpb/kvpb_go_proto_/github.com/cockroachdb/cockroach/pkg/kv/kvpb/api.pb.go:10292 +0x138
google.golang.org/grpc.(*Server).processUnaryRPC(0xc005a1d2c0, {0x6b35260, 0xc007a424e0}, 0xc007bb7d40, 0xc0068562a0, 0x95de220, 0x0)
  google.golang.org/grpc/external/org_golang_google_grpc/server.go:1336 +0xd23
google.golang.org/grpc.(*Server).handleStream(0xc005a1d2c0, {0x6b35260, 0xc007a424e0}, 0xc007bb7d40, 0x0)
  google.golang.org/grpc/external/org_golang_google_grpc/server.go:1704 +0xa2f
google.golang.org/grpc.(*Server).serveStreams.func1.2()
  google.golang.org/grpc/external/org_golang_google_grpc/server.go:965 +0x98
created by google.golang.org/grpc.(*Server).serveStreams.func1
  google.golang.org/grpc/external/org_golang_google_grpc/server.go:963 +0x28a

craig bot pushed a commit that referenced this issue Aug 28, 2023
109186: pkg/util/log: flush buffered network sinks on panic r=knz a=abarganier

Previously, our crash reporter system would flush file log sinks
as part of the process to handle a panic.

This was an incomplete process, since buffered network sinks were
not included in part of this flush process. This means that many
times, panic logs would not make it to the network target, leading
to a loss in observability.

This patch introduces `log.FlushAllSync()`, which flushes both file
and buffered network log sinks. It then updates the crash reporter
to call into this, instead of just flushing file log sinks.

`FlushAllSync()` contains timeout logic to prevent the process from
completing if one of the underlying child sinks that a bufferedSink
wraps becomes unavailable/hangs on its `output()` call.

We originally attempted to fix this in #101562, but a bug in the 
bufferedSink code led us to roll back those changes. The bug in the 
bufferedSink code has since been fixed (#108928), so we can safely 
introduce this logic again.

Release note: none

Fixes: #106345

109578: rpc: increase gRPC server timeout from 1x to 2x NetworkTimeout r=andrewbaptist a=erikgrinaker

This is intended as a conservative backport that changes as little as possible. For 23.2, we should restructure these settings a bit, possibly by removing NetworkTimeout and using independent timeouts for each component/parameter, since they have unique considerations (e.g. whether they are enforced above the Go runtime or by the OS, to what extent they are subject to RPC head-of-line blocking, etc).

---

This patch increases the gRPC server timeout from 1x to 2x NetworkTimeout. This timeout determines how long the server will wait for a TCP send to receive a TCP ack before automatically closing the connection. gRPC enforces this via the OS TCP stack by setting TCP_USER_TIMEOUT on the network socket.

While NetworkTimeout should be sufficient here, we have seen instances where this is affected by node load or other factors, so we set it to 2x NetworkTimeout to avoid spurious closed connections. An aggressive timeout is not particularly beneficial here, because the client-side timeout (in our case the CRDB RPC heartbeat) is what matters for recovery time following network or node outages -- the server side doesn't really care if the connection remains open for a bit longer.

Touches #109317.

Epic: none
Release note (ops change): The default gRPC server-side send timeout has been increased from 2 seconds to 4 seconds (1x to 2x of COCKROACH_NETWORK_TIMEOUT), to avoid spurious connection failures in certain scenarios. This can be controlled via the new environment variable COCKROACH_RPC_SERVER_TIMEOUT.

109610: kv: remove assertions around non-txn'al locking reqs r=nvanbenschoten a=nvanbenschoten

Closes #107860.
Closes #109222.
Closes #109581.
Closes #109582.

We might want to re-introduce these assertions in the future and reject these requests higher up the stack. For now, just remove them to deflake tests.

Release note: None

Co-authored-by: Alex Barganier <[email protected]>
Co-authored-by: Erik Grinaker <[email protected]>
Co-authored-by: Nathan VanBenschoten <[email protected]>
@craig craig bot closed this as completed in e980fd1 Aug 28, 2023
@github-project-automation github-project-automation bot moved this to Closed in KV Aug 28, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
A-testing Testing tools and infrastructure branch-release-22.2 Used to mark GA and release blockers, technical advisories, and bugs for 22.2 C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. T-kv KV Team
Projects
No open projects
Archived in project
Development

Successfully merging a pull request may close this issue.

4 participants