sql,admission: ERROR: liveness session expired XXXms before transaction

[cucaroach]

Multiple tenants hitting a kv server with a large batched insert load can cause this error. For example see:

#77481

Changing warmup batch size from 100 to 1000 reliably demonstrates the issue.

Jira issue: CRDB-14219

[ajwerner]

I think there's two questions here:

1. How did we get to a place where the session was about to expire, and
2. Why are we returning this error as opposed to just forcing the system to retry internally

I feel like it's possible that just kv server rate limiting is starving off session renewal, given the shape of the test. As for the error, we probably should treat is as a restart internally like we do with failing to meet a transaction deadline.

[cucaroach]

I hit this in another simpler test with just 1 node in the storage tier, in this case I wasn't getting any table statistics so I looked at error from:

> github.com/cockroachdb/cockroach/pkg/sql/stats.(*Refresher).refreshStats() github.com/cockroachdb/cockroach/pkg/sql/stats/pkg/sql/stats/automatic_stats.go:773 (hits goroutine(2072):2 total:2) (PC: 0x1a9ca91)
Warning: debugging optimized function
(dlv) p err.cause.cause
error(*github.com/cockroachdb/errors/withstack.withStack) *{
        cause: error(*github.com/cockroachdb/errors/errutil.leafError) *{
                msg: "liveness session expired 8m6.020911792s before transaction",},
        stack: *github.com/cockroachdb/errors/withstack.stack len: 11, cap: 32, [27814108,52907324,52907254,52905276,52968880,52903647,52858847,52852936,52847627,54041388,4978305],}

Then I noticed my kv node log was full of:

W220923 13:24:46.348441 301 13@kv/kvserver/replicate_queue.go:815 ⋮ [n1,replicate,s1,r122878/1:‹/Tenant/11/Table/104/1/0/968…›] 1941239  error processing replica: ‹0 of 1 live stores are able to take a new replica for the range (1 already has a voter, 0 already have a non-voter); likely not enough nodes in cluster›‹›
W220923 13:24:46.348441 301 13@kv/kvserver/replicate_queue.go:815 ⋮ [n1,replicate,s1,r122878/1:‹/Tenant/11/Table/104/1/0/968…›] 1941239 +‹trace:›
W220923 13:24:46.348441 301 13@kv/kvserver/replicate_queue.go:815 ⋮ [n1,replicate,s1,r122878/1:‹/Tenant/11/Table/104/1/0/968…›] 1941239 +‹     0.000ms      0.000ms    === operation:process replica _unfinished:1 _verbose:1 node:1 replicate: store:1 range:122878/1:/Tenant/11/Table/104/1/0/968…›
W220923 13:24:46.348441 301 13@kv/kvserver/replicate_queue.go:815 ⋮ [n1,replicate,s1,r122878/1:‹/Tenant/11/Table/104/1/0/968…›] 1941239 +‹     0.036ms      0.036ms    event:kv/kvserver/allocator/allocatorimpl/allocator.go:682 [n1,replicate,s1,r122878/1:/Tenant/11/Table/104/1/0/968…] add voter - missing voter need=3, have=1, priority=10001.00›
W220923 13:24:46.348441 301 13@kv/kvserver/replicate_queue.go:815 ⋮ [n1,replicate,s1,r122878/1:‹/Tenant/11/Table/104/1/0/968…›] 1941239 +‹     0.050ms      0.014ms    event:kv/kvserver/replicate_queue.go:864 [n1,replicate,s1,r122878/1:/Tenant/11/Table/104/1/0/968…] next replica action: add voter›
W220923 13:24:46.348441 301 13@kv/kvserver/replicate_queue.go:815 ⋮ [n1,replicate,s1,r122878/1:‹/Tenant/11/Table/104/1/0/968…›] 1941239 +‹     0.087ms      0.037ms    event:kv/kvserver/allocator/allocatorimpl/allocator.go:1037 [n1,replicate,s1,r122878/1:/Tenant/11/Table/104/1/0/968…] allocate voter: []›
W220923 13:24:46.349130 301 13@kv/kvserver/replicate_queue.go:815 ⋮ [n1,replicate,s1,r108120/1:‹/Tenant/11/Table/104/1/5/839…›] 1941240  error processing replica: ‹0 of 1 live stores are able to take a new replica for the range (1 already has a voter, 0 already have a non-voter); likely not enough nodes in cluster›‹›

So I added two more storage nodes and now its happy. So current hypothesis is lease errors occur due to under provisioned storage tier that's in an unhappy state. Should I close this or do we care about the ability to function in this situation?

[ajwerner]

If you pause in your debugger for too long, I'd expect this.

[ajwerner]

I think we close this, I'm not sure there's much to do here. The second one is #87452.

[irfansharif]

Re-enabled these tests which started tripping again in #97448. Re-opening to track:

Why are we returning this error as opposed to just forcing the system to retry internally?

And also maybe using higher AC priority for session renewal goroutines, which would help with:

How did we get to a place where the session was about to expire, and

[irfansharif]

And also maybe using higher AC priority for session renewal goroutines:

Actually the higher pri won’t help, since session renewal is bypassing AC altogether:

cockroach/pkg/sql/sqlliveness/slstorage/slstorage.go

Line 456 in 5129578

err = s.db.Txn(ctx, func(ctx context.Context, txn *kv.Txn) error {

That uses AdmissionHeader_OTHER, which hooks into:

cockroach/pkg/kv/kvserver/kvadmission/kvadmission.go

Lines 210 to 212 in 736a67e

	if source == kvpb.AdmissionHeader_OTHER {
	bypassAdmission = true
	}

[irfansharif]

Actually the higher pri won’t help, since session renewal is bypassing AC altogether.

Actually, I’m being daft. This is a multi-tenant test, so we’re actually not bypassing AC. We’re just using regular priority then for SQL session extensions.

cockroach/pkg/kv/kvserver/kvadmission/kvadmission.go

Lines 203 to 210 in 736a67e

	bypassAdmission := ba.IsAdmin()
	source := ba.AdmissionHeader.Source
	if !roachpb.IsSystemTenantID(tenantID.ToUint64()) {
	// Request is from a SQL node.
	bypassAdmission = false
	source = kvpb.AdmissionHeader_FROM_SQL
	}
	if source == kvpb.AdmissionHeader_OTHER {

I'll go back to explicitly using high pri first.