sql: unexpected "rangefeeds require kv.rangefeed.enabled" on system tables

[RaduBerinde]

I am running into a problem which seems to be caused by system table rangefeeds in the tenant not working. I distilled the change I was working on to just a delay during tenant initialization.

Apply this diff:

diff --git a/pkg/server/node.go b/pkg/server/node.go
index 3ad254081e..4dd5fd236a 100644
--- a/pkg/server/node.go
+++ b/pkg/server/node.go
@@ -1390,6 +1390,7 @@ func (n *Node) TenantSettings(
 ) error {
 	ctx := n.storeCfg.AmbientCtx.AnnotateCtx(stream.Context())
 	ctxDone := ctx.Done()
+	time.Sleep(10 * time.Second)
 
 	// TODO(radu): implement this. For now we just respond with an initial event
 	// so the tenant can initialize.

Then run:

make test PKG=./pkg/ccl/logictestccl 'TESTS=TestTenantLogic/3node-tenant#01/tenant$$' TESTFLAGS='-v -show-logs' TESTTIMEOUT=30s

Sometimes the test passes, but usually it gets stuck and you see this in logs:

W220209 20:33:47.697524 5665 kv/kvclient/rangefeed/rangefeed.go:301  [nsql1,rangefeed=sql_instances] 190  rangefeed failed 0 times, restarting: kv/kvserver/replica_rangefeed.go:157: rangefeeds require the kv.rangefeed.enabled setting. See https://www.cockroachlabs.com/docs/v22.1/change-data-capture.html#enable-rangefeeds-to-reduce-latency
W220209 20:33:47.699613 2113 kv/kvclient/rangefeed/rangefeed.go:301  [nsql1,rangefeed=table-stats-cache] 191  rangefeed failed 0 times, restarting: kv/kvserver/replica_rangefeed.go:157: rangefeeds require the kv.rangefeed.enabled setting. See https://www.cockroachlabs.com/docs/v22.1/change-data-capture.html#enable-rangefeeds-to-reduce-latenc> y
W220209 20:33:47.701328 5772 kv/kvclient/rangefeed/rangefeed.go:301  [nsql1,rangefeed=settings-watcher] 192  rangefeed failed 0 times, restarting: kv/kvserver/replica_rangefeed.go:157: rangefeeds require the kv.rangefeed.enabled setting. See https://www.cockroachlabs.com/docs/v22.1/change-data-capture.html#enable-rangefeeds-to-reduce-latency
W220209 20:33:47.703405 5775 kv/kvclient/rangefeed/rangefeed.go:301  [nsql1,rangefeed=system-config-cache] 193  rangefeed failed 0 times, restarting: kv/kvserver/replica_rangefeed.go:157: rangefeeds require the kv.rangefeed.enabled setting. See https://www.cockroachlabs.com/docs/v22.1/change-data-capture.html#enable-rangefeeds-to-reduce-late> ncy
W220209 20:33:47.712925 6384 kv/kvclient/rangefeed/rangefeed.go:301  [nsql?,rangefeed=table-stats-cache] 194  rangefeed failed 0 times, restarting: kv/kvserver/replica_rangefeed.go:157: rangefeeds require the kv.rangefeed.enabled setting. See https://www.cockroachlabs.com/docs/v22.1/change-data-capture.html#enable-rangefeeds-to-reduce-latenc> y

This is on 4df7f50.

@ajwerner suspects #74555.

[RaduBerinde]

@yuzefovich ran into this as well (he hit ERROR: setting updated but timed out waiting to read new value when setting a cluster setting). I reproduced with his data directory and saw the same logs as above.

[ajwerner]

#76420 is something and attacks the heart of the problem. There's still some rough edges to iron out here.

[RaduBerinde]

@yuzefovich ran into this as well (he hit ERROR: setting updated but timed out waiting to read new value when setting a cluster setting). I reproduced with his data directory and saw the same logs as above.

Some more info here - Yahor ran into a problem and he gave me the cockroach-data dir. I started a regular node with that dir and saw these messages:

W220211 03:49:13.566659 530 kv/kvclient/rangefeed/rangefeed.go:301 ⋮ [n1,rangefeed=‹sql_instances›] 205  rangefeed failed 9 times, restarting: ‹kv/kvserver/replica_rangefeed.go›:157: rangefeeds require the kv.rangefeed.enabled setting. See ‹https://www.cockroachlabs.com/docs/v22.1/change-data-capture.html#enable-rangefeeds-to-reduce-latency›
W220211 03:49:13.635930 891 kv/kvclient/rangefeed/rangefeed.go:301 ⋮ [n1,rangefeed=‹settings-watcher›] 206  rangefeed failed 9 times, restarting: ‹kv/kvserver/replica_rangefeed.go›:157: rangefeeds require the kv.rangefeed.enabled setting. See ‹https://www.cockroachlabs.com/docs/v22.1/change-data-capture.html#enable-rangefeeds-to-reduce-latency›
I220211 03:49:13.715993 497 sql/sqlstats/persistedsqlstats/flush.go:32 ⋮ [n1] 207  flushing 2 stmt/txn fingerprints (10240 bytes) after 1.0089529s
W220211 03:49:13.861032 177 kv/kvclient/rangefeed/rangefeed.go:301 ⋮ [n1,rangefeed=‹table-stats-cache›] 208  rangefeed failed 10 times, restarting: ‹kv/kvserver/replica_rangefeed.go›:157: rangefeeds require the kv.rangefeed.enabled setting. See ‹https://www.cockroachlabs.com/docs/v22.1/change-data-capture.html#enable-rangefeeds-to-reduce-latency›
W220211 03:49:14.084262 299 kv/kvclient/rangefeed/rangefeed.go:301 ⋮ [n1,rangefeed=‹system-config-cache›] 209  rangefeed failed 9 times, restarting: ‹kv/kvserver/replica_rangefeed.go›:157: rangefeeds require the kv.rangefeed.enabled setting. See ‹https://www.cockroachlabs.com/docs/v22.1/change-data-capture.html#enable-rangefeeds-to-reduce-latency›

And I was able to reproduce ERROR: setting updated but timed out waiting to read new value when changing a cluster setting.

[ajwerner]

@yuzefovich ran into this as well (he hit ERROR: setting updated but timed out waiting to read new value when setting a cluster setting). I reproduced with his data directory and saw the same logs as above.

Any chance I can get this data directory? On some level it's going to have to do with the span configs being incorrect. A scan of SELECT crdb_internal.pretty_key(start_key, 0), crdb_internal.pretty_key(end_key, 0), crdb_internal.pb_to_json('cockroach.roachpb.SpanConfig', config) from system.span_configurations will hold good clues.

[yuzefovich]

Sent you a link on slack (out of paranoia of that directory containing some confidential information).

[ajwerner]

Classic lack of version upgrade testing ☹️. There's a funny problem here. We watch for changes in span configs using a rangefeed. We used to decide if rangefeeds were enabled by looking at the keys of the replica but we stripped that in https://github.com/cockroachdb/cockroach/pull/74555/files#diff-b080aecf7d979c0b5a4c43973db709d0d866f137cb4e961ebfc0d979ad22c003. The problem is, in the mixed version state, we won't support the rangefeeds we need. That's bad and means we need to put the old logic back. The good news about the old logic is it's all still valid.

I'm not getting some ambient feels of concern about upgrade considerations for the tenants themselves, but I think if we just wholesale put the old logic back, we'll be fine.

[ajwerner]

I think @RaduBerinde you'll be fine with #76420 for new tenants in new cluster and that new clusters bootstrapped off of master will be fine. We'll definitely need to do some mixed version testing. Sort of appalling that there's no mixed version test which sets a cluster setting.

[arulajmani]

Maybe I'm missing something, but I'm not entirely sure how we end up in this mixed version case. Looking here:

cockroach/pkg/config/system.go

Lines 311 to 319 in 4b8258c

	if id <= keys.MaxReservedDescID {
	// We enable rangefeeds for system tables; various internal
	// subsystems (leveraging system tables) rely on rangefeeds to
	// function.
	spanConfig.RangefeedEnabled = true
	// We exclude system tables from strict GC enforcement, it's
	// only really applicable to user tables.
	spanConfig.GCPolicy.IgnoreStrictEnforcement = true
	}

Doesn't this mean we should be supporting the rangefeeds we need? It also looks like we have this logic to support rangefeeds if a config is not explicitly set on a replica.

---

After typing all of that, I came across this logic where we seem to be swallowing an error and applying the default span config on the replica -- maybe this is what's causing the issue?

cockroach/pkg/kv/kvserver/store.go

Lines 2316 to 2328 in 14001c5

	conf, err := sysCfg.GetSpanConfigForKey(ctx, key)
	if err != nil {
	if log.V(1) {
	log.Infof(context.TODO(), "failed to get span config for key %s", key)
	}
	conf = s.cfg.DefaultSpanConfig
	}
	if s.cfg.SpanConfigsDisabled ||
	!spanconfigstore.EnabledSetting.Get(&s.ClusterSettings().SV) ||
	!s.cfg.Settings.Version.IsActive(ctx, clusterversion.EnableSpanConfigStore) {
	repl.SetSpanConfig(conf)
	}

If we don't want to bring back the old key stripping logic, maybe we can set RangefeedEnabled to be true on the DefaultSpanConfig that we have on the kvserver.StoreConfig? Essentially, moving this logic a layer above:

cockroach/pkg/server/server.go

Lines 540 to 559 in 6e1cbfe

	// We use the span configs infra to control whether rangefeeds are
	// enabled on a given range. At the moment this only applies to
	// system tables (on both host and secondary tenants). We need to
	// consider two things:
	// - The sql-side reconciliation process runs asynchronously. When
	// the config for a given range is requested, we might not yet have
	// it, thus falling back to the static config below.
	// - Various internal subsystems rely on rangefeeds to function.
	//
	// Consequently, we configure our static fallback config to actually
	// allow rangefeeds. As the sql-side reconciliation process kicks
	// off, it'll install the actual configs that we'll later consult.
	// For system table ranges we install configs that allow for
	// rangefeeds. Until then, we simply allow rangefeeds when a more
	// targeted config is not found.
	fallbackConf := storeCfg.DefaultSpanConfig
	fallbackConf.RangefeedEnabled = true
	// We do the same for opting out of strict GC enforcement; it
	// really only applies to user table ranges
	fallbackConf.GCPolicy.IgnoreStrictEnforcement = true

[yuzefovich]

@ajwerner should this issue be closed by #76420?

[irfansharif]

Yes, I think so. There's a migration bug theorized above, but I don't think it holds -- sending a PR with a test to prove it. As for how #74555 could affect the non-system tenant, I'm not sure yet. Do you have a repro I could use to see what you were seeing?

[irfansharif]

I took a look at the zipped store being referenced above, confirming that I saw the same as described -- rangefeeds were wedged on server startup. I also noticed that if the server process was restarted, things worked just fine. Eventually I just disabled the reconciliation job and poked at the store's contents of system.span_configurations, and noticed that even for system tables, it didn't have config.RangefeedEnabled set. I'm guessing that the store was created off of a binary that did not have #74555. Because the span config proto did not know about this field, on KV store start up when scanning from that table, we applied config.RangefeedEnabled == false for system database ranges, blocking all rangefeeds. The reason restarting the server seemed to resolve the problem is because the first time the server range, the reconciliation job will have successfully run, overwriting system.span_configuration protos with the right field set. The reason it was not picked up by process the first time time is because the per-store component that listens in on updates to the table also made use of rangefeeds, so was similarly wedged. This was not a problem post-restart.

Anyway, I don't think there's anything to do here, not a bug AFAICT. #76466 confirms that mixed-version state with rangefeeds work just fine; we were careful about hardcoding the right defaults in #74555.