kvserver: v22.1.4: nil pointer in poisonInflightLatches #86547

cockroach-teamcity · 2022-08-22T10:01:41Z

This issue was autofiled by Sentry. It represents a crash or reported error on a live cluster with telemetry enabled.

Sentry link: https://sentry.io/organizations/cockroach-labs/issues/3521479942/?referrer=webhooks_plugin

Panic message:

panic.go:1038: runtime error: invalid memory address or nil pointer dereference
(1) attached stack trace
-- stack trace:
| runtime.gopanic
| GOROOT/src/runtime/panic.go:1038
| runtime.panicmem
| GOROOT/src/runtime/panic.go:221
| runtime.sigpanic
| GOROOT/src/runtime/signal_unix.go:735
| github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).poisonInflightLatches
| github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_raft.go:1384
| github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*replicaCircuitBreaker).asyncProbe.func1
| github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_circuit_breaker.go:218
| github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2
| github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:494
| runtime.goexit
| GOROOT/src/runtime/asm_amd64.s:1581
Wraps: (2) runtime error: invalid memory address or nil pointer dereference
Error types: (1) *withstack.withStack (2) runtime.errorString
-- report composition:
runtime.errorString
panic.go:1038: *withstack.withStack (top exception)

Stacktrace (expand for inline code snippets):

GOROOT/src/runtime/panic.go#L1037-L1039 in runtime.gopanic
GOROOT/src/runtime/panic.go#L220-L222 in runtime.panicmem
GOROOT/src/runtime/signal_unix.go#L734-L736 in runtime.sigpanic
https://github.com/cockroachdb/cockroach/blob/3c6c8933f578a7fd140e24a603d6ec64c6b7a834/pkg/kv/kvserver/pkg/kv/kvserver/replica_raft.go#L1383-L1385 in pkg/kv/kvserver.(*Replica).poisonInflightLatches
https://github.com/cockroachdb/cockroach/blob/3c6c8933f578a7fd140e24a603d6ec64c6b7a834/pkg/kv/kvserver/pkg/kv/kvserver/replica_circuit_breaker.go#L217-L219 in pkg/kv/kvserver.(*replicaCircuitBreaker).asyncProbe.func1

cockroach/pkg/util/stop/stopper.go

Lines 493 to 495 in 3c6c893

in pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2
GOROOT/src/runtime/asm_amd64.s#L1580-L1582 in runtime.goexit

GOROOT/src/runtime/panic.go in runtime.gopanic at line 1038
GOROOT/src/runtime/panic.go in runtime.panicmem at line 221
GOROOT/src/runtime/signal_unix.go in runtime.sigpanic at line 735
pkg/kv/kvserver/pkg/kv/kvserver/replica_raft.go in pkg/kv/kvserver.(*Replica).poisonInflightLatches at line 1384
pkg/kv/kvserver/pkg/kv/kvserver/replica_circuit_breaker.go in pkg/kv/kvserver.(*replicaCircuitBreaker).asyncProbe.func1 at line 218
pkg/util/stop/stopper.go in pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2 at line 494
GOROOT/src/runtime/asm_amd64.s in runtime.goexit at line 1581

Tag	Value
Cockroach Release	`v22.1.4`
Cockroach SHA:	`3c6c893`
Platform	linux amd64
Distribution	CCL
Environment	v22.1.4
Command	server
Go Version	``
# of CPUs
# of Goroutines

Jira issue: CRDB-18809

Epic CRDB-39898

The text was updated successfully, but these errors were encountered:

blathers-crl · 2022-09-19T20:18:16Z

cc @cockroachdb/replication

erikgrinaker · 2022-09-19T20:52:43Z

Can you have a look @tbg?

tbg · 2022-09-20T08:47:39Z

This panics here:

cockroach/pkg/kv/kvserver/replica_raft.go

Line 1384 in d10bde7

if p.ec.g.Req.PoisonPolicy == poison.Policy_Error {

At this point we know that p.ec is not nil. Since .Req.PoisonPolicy all sits on *Guard, it must be the case that p.ec.g is nil:

cockroach/pkg/kv/kvserver/replica_send.go

Lines 1159 to 1163 in 0a2396a

    
           type endCmds struct { 
        
           	repl *Replica 
        
           	g    *concurrency.Guard 
        
           	st   kvserverpb.LeaseStatus // empty for follower reads 
        
           }

I poked around a bit and I'm not aware that we should ever have a proposal with a nil *Guard in the proposals map. It is possible for SequenceReq to return a nil *Guard, but this is the case in which it directly returns a request, and such proposals ought not to end up below raft.

@nvanbenschoten do you expect to see a nil Guard here?

tbg · 2022-09-26T15:40:11Z

@nvanbenschoten via DM

I did find that in endCmds.poison, we have an // Already cleared. branch. That indicates to me that it is possible to have a proposal with a nil *Guard in the proposals map.

What's implicit here is that Nathan does not expect endCmds to be created and put into the map with a nil Guard, it must've been zeroed out later, probably as part of ec.done().

tbg · 2022-10-10T20:44:50Z

Looked at this again a bit. Still haven't sussed it all out but I think it's reasonable to assume that some proposals in the map can be finished (so their endCmds are cleared) without strict sync with the proposals map. It's cleared only from p.finishApplication but that method has a few callers including from the proposal buf, which also has to deal with reproposals, etc.
Will scrutinize all of this code and probably send a PR that makes it a bit clearer on master. On the older releases (22.1 etc) we should just backport the nil check for p.ec.g.

msbutler · 2022-12-19T21:13:48Z

a heads up that this failure surfaced in a nightly run of backupccl's TestDataDriven/restore-schema-only-multiregion here. Unfortunately, we were not quick enough to triage before artifact deletion. Stressing this test on master has lead to a different failure I've outlined here related to server startup.

stevendanna · 2023-01-04T11:22:53Z

We've seen a similar looking failure again on TestDataDriven. We have aftifacts this time if they are helpful: https://teamcity.cockroachdb.com/repository/download/Cockroach_Nightlies_StressBazel/8179790:id/tmp/_tmp/95e138e66d69292427dfb9528cf06d04/logTestDataDriven4271694788/backupccltest.log

E230104 08:37:44.513251 500410339 1@util/log/logcrash/crash_reporting.go:188 â‹® [n1,s1,r49/1:â€¹/Table/4{7-8}â€º] 62627  a panic has occurred!
E230104 08:37:44.513251 500410339 1@util/log/logcrash/crash_reporting.go:188 â‹® [n1,s1,r49/1:â€¹/Table/4{7-8}â€º] 62627 +runtime error: invalid memory address or nil pointer dereference
E230104 08:37:44.513251 500410339 1@util/log/logcrash/crash_reporting.go:188 â‹® [n1,s1,r49/1:â€¹/Table/4{7-8}â€º] 62627 +(1) attached stack trace
E230104 08:37:44.513251 500410339 1@util/log/logcrash/crash_reporting.go:188 â‹® [n1,s1,r49/1:â€¹/Table/4{7-8}â€º] 62627 +  -- stack trace:
E230104 08:37:44.513251 500410339 1@util/log/logcrash/crash_reporting.go:188 â‹® [n1,s1,r49/1:â€¹/Table/4{7-8}â€º] 62627 +  | runtime.gopanic
E230104 08:37:44.513251 500410339 1@util/log/logcrash/crash_reporting.go:188 â‹® [n1,s1,r49/1:â€¹/Table/4{7-8}â€º] 62627 +  | 	GOROOT/src/runtime/panic.go:884
E230104 08:37:44.513251 500410339 1@util/log/logcrash/crash_reporting.go:188 â‹® [n1,s1,r49/1:â€¹/Table/4{7-8}â€º] 62627 +  | runtime.panicmem
E230104 08:37:44.513251 500410339 1@util/log/logcrash/crash_reporting.go:188 â‹® [n1,s1,r49/1:â€¹/Table/4{7-8}â€º] 62627 +  | 	GOROOT/src/runtime/panic.go:260
E230104 08:37:44.513251 500410339 1@util/log/logcrash/crash_reporting.go:188 â‹® [n1,s1,r49/1:â€¹/Table/4{7-8}â€º] 62627 +  | runtime.sigpanic
E230104 08:37:44.513251 500410339 1@util/log/logcrash/crash_reporting.go:188 â‹® [n1,s1,r49/1:â€¹/Table/4{7-8}â€º] 62627 +  | 	GOROOT/src/runtime/signal_unix.go:835
E230104 08:37:44.513251 500410339 1@util/log/logcrash/crash_reporting.go:188 â‹® [n1,s1,r49/1:â€¹/Table/4{7-8}â€º] 62627 +  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*Replica).poisonInflightLatches
E230104 08:37:44.513251 500410339 1@util/log/logcrash/crash_reporting.go:188 â‹® [n1,s1,r49/1:â€¹/Table/4{7-8}â€º] 62627 +  | 	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_raft.go:1363
E230104 08:37:44.513251 500410339 1@util/log/logcrash/crash_reporting.go:188 â‹® [n1,s1,r49/1:â€¹/Table/4{7-8}â€º] 62627 +  | github.com/cockroachdb/cockroach/pkg/kv/kvserver.(*replicaCircuitBreaker).asyncProbe.func1
E230104 08:37:44.513251 500410339 1@util/log/logcrash/crash_reporting.go:188 â‹® [n1,s1,r49/1:â€¹/Table/4{7-8}â€º] 62627 +  | 	github.com/cockroachdb/cockroach/pkg/kv/kvserver/pkg/kv/kvserver/replica_circuit_breaker.go:200
E230104 08:37:44.513251 500410339 1@util/log/logcrash/crash_reporting.go:188 â‹® [n1,s1,r49/1:â€¹/Table/4{7-8}â€º] 62627 +  | github.com/cockroachdb/cockroach/pkg/util/stop.(*Stopper).RunAsyncTaskEx.func2
E230104 08:37:44.513251 500410339 1@util/log/logcrash/crash_reporting.go:188 â‹® [n1,s1,r49/1:â€¹/Table/4{7-8}â€º] 62627 +  | 	github.com/cockroachdb/cockroach/pkg/util/stop/stopper.go:470
E230104 08:37:44.513251 500410339 1@util/log/logcrash/crash_reporting.go:188 â‹® [n1,s1,r49/1:â€¹/Table/4{7-8}â€º] 62627 +  | runtime.goexit
E230104 08:37:44.513251 500410339 1@util/log/logcrash/crash_reporting.go:188 â‹® [n1,s1,r49/1:â€¹/Table/4{7-8}â€º] 62627 +  | 	GOROOT/src/runtime/asm_amd64.s:1594

tbg · 2023-01-06T06:12:31Z

I think it will be easy to "fix" the bug - just add a nil check - but I think there is something to be understood yet. I am still not seeing how we can end up with a proposal in r.mu.proposals that is finished.

I went through all of the callers to endCmds.done below and verified that they all make sure that the proposal is not in the map by the time .done() is called.

Most of them "obviously" do (for some of them it's clear that the proposal is never added to the map in the first place).
There are two exceptions:

`AckOutcomeAndFinish`

At the beginning of command application, a replicaAppBatch will be created and will grab¹ the proposals from the map (removing them). However, it doesn't do this for all proposals, only for those that aren't superseded by a reproposal with a higher LeaseAppliedIndex². The superseded ones could be of interested - they are still in the map during application, so perhaps we're signalling them? There are in fact potential problems here.

The first is in the code below, which will signal all proposals, including superseded ones, meaning they will be signaled & stay in the map:

cockroach/pkg/kv/kvserver/apply/task.go

Lines 260 to 270 in edf6976

    
           if err := t.applyOneBatch(ctx, iter); err != nil { 
        
           	// If the batch threw an error, reject all remaining commands in the 
        
           	// iterator to avoid leaking resources or leaving a proposer hanging. 
        
           	// 
        
           	// NOTE: forEachCmdIter closes iter. 
        
           	if rejectErr := forEachCmdIter(ctx, iter, func(cmd Command, ctx context.Context) error { 
        
           		return cmd.AckErrAndFinish(ctx, err) 
        
           	}); rejectErr != nil { 
        
           		return rejectErr 
        
           	} 
        
           	return err

The one error we expect to see from applyOneBatch (thus triggering this code path) is ErrRemoved. It's unlikely that we saw this one in this instance, since the system was basically defunct for over a minute and so replicaGC is not too likely, plus we don't see log messages that should have occurred prior to the crash. But I'll make a note that something is wrong here.

I also considered whether we might be signaling proposals that are in the map in the error path here:

cockroach/pkg/kv/kvserver/replica_application_result.go

Lines 111 to 120 in 54e3708

    
           if pErr != nil { 
        
           	log.Warningf(ctx, "failed to repropose with new lease index: %s", pErr) 
        
           	cmd.response.Err = pErr 
        
           } else { 
        
           	// Unbind the entry's local proposal because we just succeeded 
        
           	// in reproposing it and we don't want to acknowledge the client 
        
           	// yet. 
        
           	cmd.proposal = nil 
        
           	return 
        
           }

but I had recently convinced myself² that a proposal that hits this path was necessarily removed from the map already, in retrieveLocalProposals¹.

`refreshProposalsLocked`

This one is more interesting. Even though that method holds the appropriate locks throughout and does remove commands from the map prior to finishing them (in the few cases in which it does do that), what it does do in the common case is hand proposals that are in the map back to the proposal buffer (without finishing them):

cockroach/pkg/kv/kvserver/replica_raft.go

Lines 1345 to 1347 in ac3e633

    
           for _, p := range reproposals { 
        
           	log.Eventf(p.ctx, "re-submitting command %x to Raft: %s", p.idKey, reason) 
        
           	if err := r.mu.proposalBuf.ReinsertLocked(ctx, p); err != nil {

This is possibly problematic - we now have a (yet unfinished, presumably) proposal in both the map and the proposal buffer. Could the proposal now be applied, finished, removed from the map but then be reinserted³ due to being present in the proposal buffer? I'm actually not convinced this can happen, because the proposal buffer is flushed right at the beginning of raft processing (which includes entry application), meaning that by the time we might be applying the proposal the proposal buffer has already been emptied out⁴ and won't re-insert into the map.

cockroach/pkg/kv/kvserver/replica_raft.go

Lines 718 to 719 in ac3e633

    
           err := r.withRaftGroupLocked(true, func(raftGroup *raft.RawNode) (bool, error) { 
        
           	numFlushed, err := r.mu.proposalBuf.FlushLockedWithRaftGroup(ctx, raftGroup)

Next steps

The lifecycle of a proposal is pretty ad-hoc but there is clearly an invariant I am assuming should hold - that there isn't ever a finished proposal in the proposal map. We are not checking this invariant, but we should. We add to the map in a single place only³ and should verify this here. If we then still see the crash but not the assertion - we know the proposal was finished while remaining in the map, still in violation of the invariant.

As outlined above, we know of at least one invariant violation (the snippet in the AckOutcomeAndFinish section) but maybe I missed another one. Actually, revisiting the log of the failing test above, maybe it is replicaGC-related after all, since this is a multi-region test and I see the replicaGCQueue repeatedly run into the circuit breaker. But I'm still unsure why there isn't any logging⁵ then.

The conjecture in cockroachdb#86547 is that a finished proposal somehow makes its way into the proposal map, most likely by never being removed prior to being finished. This commit adds an assertion that we're never outright *inserting* a finished proposals, and better documents the places in which we're running a risk of violating the invariant. It also clarifies the handling of proposals in an apply batch when a replication change that removes the replica is encountered. I suspected that this could lead to a case in which proposals would be finished despite remaining in the proposals map. Upon inspection this turned out to be incorrect - the map (at least by code inspection) is empty at that point, so the invariant holds trivially. Unfortunately, that leaves me without an explanation for cockroachdb#86547, but the newly added invariants may prove helpful. Touches cockroachdb#86547.

msbutler · 2023-01-24T12:18:17Z

@tbg, this unrelated test has been frequently failing due to this error. If you think the review process for #94825 will take some time, I may skip the test to avoid CI flakiness.

I still don't understand how we can get a finished endCmds here, but while I scratch my head we don't need to be collecting CI failures. Touches cockroachdb#86547. Epic: none Release note: None

95744: kvserver: don't NPE in poisonInflightLatches r=erikgrinaker a=tbg I still don't understand how we can get a finished endCmds here, but while I scratch my head we don't need to be collecting CI failures. Touches #86547. Closes #94209. Epic: none Release note: None Co-authored-by: Tobias Grieger <[email protected]>

The conjecture in cockroachdb#86547 is that a finished proposal somehow makes its way into the proposal map, most likely by never being removed prior to being finished. This commit adds an assertion that we're never outright *inserting* a finished proposals, and better documents the places in which we're running a risk of violating the invariant. It also clarifies the handling of proposals in an apply batch when a replication change that removes the replica is encountered. I suspected that this could lead to a case in which proposals would be finished despite remaining in the proposals map. Upon inspection this turned out to be incorrect - the map (at least by code inspection) is empty at that point, so the invariant holds trivially. Unfortunately, that leaves me without an explanation for cockroachdb#86547, but the newly added invariants may prove helpful. Touches cockroachdb#86547.

94825: kvserver: prevent finished proposal from being present in proposals map r=nvanbenschoten a=tbg The conjecture in #86547 is that a finished proposal somehow makes its way into the proposal map, most likely by never being removed prior to being finished. This commit adds an assertion that we're never outright *inserting* a finished proposals, and better documents the places in which we're running a risk of violating the invariant. It also clarifies the handling of proposals in an apply batch when a replication change that removes the replica is encountered. I suspected that this could lead to a case in which proposals would be finished despite remaining in the proposals map. Upon inspection this turned out to be incorrect - the map (at least by code inspection) is empty at that point, so the invariant holds trivially. Unfortunately, that leaves me without an explanation for #86547, but the newly added invariants may prove helpful. Touches #86547. Epic: None Release note: None Co-authored-by: Tobias Grieger <[email protected]>

tbg · 2023-03-15T12:31:34Z

Unassigning since I'm no longer working on this and we've made the code path resilient to avoid the crash. It's likely that Epic CRDB-25287 will solve the underlying problem, which likely had to do with a finished proposal being re-inserted into the proposals map, which is something we know is possible at the moment. (This is not thought to cause double-application but can cause crashes in code that assumes it's not possible).

tbg · 2023-07-18T12:00:20Z

The reproposal path has been simplified quite a bit as a result of CRDB-25287 and the problem is more or less understood:

https://github.com/cockroachdb/cockroach/pull/106750/files#diff-58a18041db5281b4abe232561907fa9683d5c58c6704679e82dc8964aab4ecfaR1304-R1316

The work-around is still in place above and below:

cockroach/pkg/kv/kvserver/replica_raft.go

Lines 1496 to 1512 in fe1c4a0

    
           func (r *Replica) poisonInflightLatches(err error) { 
        
           	r.raftMu.Lock() 
        
           	defer r.raftMu.Unlock() 
        
           	r.mu.Lock() 
        
           	defer r.mu.Unlock() 
        
           	for _, p := range r.mu.proposals { 
        
           		p.ec.poison() 
        
           		// TODO(tbg): find out how `p.ec.done()` can have been called at this point, 
        
           		// See: https://github.com/cockroachdb/cockroach/issues/86547 
        
           		if p.ec.g != nil && p.ec.g.Req.PoisonPolicy == poison.Policy_Error { 
        
           			aErr := kvpb.NewAmbiguousResultError(err) 
        
           			// NB: this does not release the request's latches. It's important that 
        
           			// the latches stay in place, since the command could still apply. 
        
           			p.signalProposalResult(makeProposalResultErr(aErr)) 
        
           		} 
        
           	} 
        
           }

but armed with this comment

https://github.com/cockroachdb/cockroach/pull/106750/files#diff-488a090afc4b6eaf56cd6d13b347bac67cb3313ce11c49df9ee8cd95fd73b3e8R57-R73

we should feel comfortable going through another round of assertions (best using must¹). Either way, no user should currently be impacted by this. I'll keep it open, though.

https://github.com/cockroachdb/cockroach/pull/106508 ↩

cockroach-teamcity added C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. O-sentry Originated from an in-the-wild panic report. labels Aug 22, 2022

yuzefovich changed the title sentry: panic.go:1038: runtime error: invalid memory address or nil pointer dereference (1) attached stack trace -- stack trace: | runtime.gopanic | GOROOT/src/runtime/panic.go:1038 | runtime.panicme... kvserver: v22.1.4: nil pointer in poisonInflightLatches Aug 29, 2022

blathers-crl bot added the T-kv KV Team label Aug 29, 2022

exalate-issue-sync bot added T-kv-replication and removed T-kv KV Team labels Sep 19, 2022

erikgrinaker assigned tbg Sep 19, 2022

msbutler mentioned this issue Dec 19, 2022

ccl/backupccl: TestDataDriven failed #93492

Closed

tbg mentioned this issue Jan 6, 2023

kvserver: prevent finished proposal from being present in proposals map #94825

Merged

tbg mentioned this issue Jan 24, 2023

kvserver: don't NPE in poisonInflightLatches #95744

Merged

tbg removed their assignment Mar 15, 2023

yuzefovich mentioned this issue Apr 7, 2023

sentry: panic.go:884: runtime error: invalid memory address or nil pointer dereference (1) attached stack trace -- stack trace: | runtime.gopanic | GOROOT/src/runtime/panic.go:884 | runtime.panicmem ... #97686

Closed

exalate-issue-sync bot assigned tbg May 30, 2023

tbg removed their assignment Jul 18, 2023

tbg mentioned this issue Jul 25, 2023

kvserver: span assertions fire in replication layer #107521

Closed

exalate-issue-sync bot added T-kv KV Team and removed T-kv-replication labels Jun 28, 2024

github-project-automation bot added this to KV Aug 28, 2024

github-project-automation bot moved this to Incoming in KV Aug 28, 2024

tbg closed this as completed Sep 17, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

kvserver: v22.1.4: nil pointer in poisonInflightLatches #86547

kvserver: v22.1.4: nil pointer in poisonInflightLatches #86547

cockroach-teamcity commented Aug 22, 2022 •

edited by exalate-issue-sync bot

Loading

blathers-crl bot commented Sep 19, 2022

erikgrinaker commented Sep 19, 2022

tbg commented Sep 20, 2022

tbg commented Sep 26, 2022

tbg commented Oct 10, 2022

msbutler commented Dec 19, 2022 •

edited

Loading

stevendanna commented Jan 4, 2023

tbg commented Jan 6, 2023 •

edited

Loading

msbutler commented Jan 24, 2023

tbg commented Mar 15, 2023

tbg commented Jul 18, 2023

kvserver: v22.1.4: nil pointer in poisonInflightLatches #86547

kvserver: v22.1.4: nil pointer in poisonInflightLatches #86547

Comments

cockroach-teamcity commented Aug 22, 2022 • edited by exalate-issue-sync bot Loading

blathers-crl bot commented Sep 19, 2022

erikgrinaker commented Sep 19, 2022

tbg commented Sep 20, 2022

tbg commented Sep 26, 2022

tbg commented Oct 10, 2022

msbutler commented Dec 19, 2022 • edited Loading

stevendanna commented Jan 4, 2023

tbg commented Jan 6, 2023 • edited Loading

AckOutcomeAndFinish

refreshProposalsLocked

Next steps

Footnotes

msbutler commented Jan 24, 2023

tbg commented Mar 15, 2023

tbg commented Jul 18, 2023

Footnotes

cockroach-teamcity commented Aug 22, 2022 •

edited by exalate-issue-sync bot

Loading

msbutler commented Dec 19, 2022 •

edited

Loading

tbg commented Jan 6, 2023 •

edited

Loading

`AckOutcomeAndFinish`

`refreshProposalsLocked`