ccl/streamingccl/streamingest: TestStreamingReplanOnLag failed

[cockroach-teamcity]

ccl/streamingccl/streamingest.TestStreamingReplanOnLag failed on master @ a2f1f379ee52ceee2b2aa6769f1fa162f8d6b8a7:

=== RUN   TestStreamingReplanOnLag
    test_log_scope.go:170: test logs captured to: outputs.zip/logTestStreamingReplanOnLag4262448888
    test_log_scope.go:81: use -show-logs to present logs inline
    testutils.go:488: condition failed to evaluate within 45s: from testutils.go:521: waiting for stream ingestion job progress 1710827875.000000000,0 to advance beyond 1710827877.574577007,0
    panic.go:626: -- test log scope end --
test logs left over in: outputs.zip/logTestStreamingReplanOnLag4262448888
--- FAIL: TestStreamingReplanOnLag (53.50s)

Parameters:

• attempt=1
• run=1
• shard=15

Help

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

/cc @cockroachdb/disaster-recovery

This test on roachdash | Improve this report!

Jira issue: CRDB-36820

[msbutler]

failure unrelated to actual test, so likely an infra flake

[rickystewart]

@msbutler I'm not sure about that.

1. This test failed in 80% of the 30 runs that happened last night. I find "infra flake" to be a dubious explanation for why that happened.
2. The test seems to be failing with similar symptoms elsewhere, e.g. example

[stevendanna]

I took a peak at the logs on this one and the behaviour is relatively confusing to me. I'll backfill some notes but I'm gonna bump this to P1.

[stevendanna]

Here is what I find confusing:

I240319 05:58:13.895615 26373 ccl/streamingccl/streamproducer/event_stream.go:93 ⋮ [T1,Vsystem,n1,client=127.0.0.1:47792,hostssl,user=root] 778  starting physical replication event stream: tenant=10 initial_scan_timestamp=1710827892.699424453,0 previous_replicated_time=0,0
I240319 05:58:13.895679 26373 ccl/streamingccl/streamproducer/event_stream.go:140 ⋮ [T1,Vsystem,n1,client=127.0.0.1:47792,hostssl,user=root] 779  starting event stream with initial scan at 1710827892.699424453,0
I240319 05:58:13.901532 26258 ccl/streamingccl/streamingest/ingest_span_configs.go:307 ⋮ [T1,Vsystem,n1,job=‹REPLICATION STREAM INGESTION id=952754151792803843›] 780  flushing full span configuration state (49 records)
I240319 05:58:13.908532 26389 ccl/streamingccl/streamproducer/event_stream.go:93 ⋮ [T1,Vsystem,n3,client=127.0.0.1:39846,hostssl,user=root] 781  starting physical replication event stream: tenant=10 initial_scan_timestamp=1710827892.699424453,0 previous_replicated_time=0,0
I240319 05:58:13.908600 26389 ccl/streamingccl/streamproducer/event_stream.go:140 ⋮ [T1,Vsystem,n3,client=127.0.0.1:39846,hostssl,user=root] 782  starting event stream with initial scan at 1710827892.699424453,0
I240319 05:58:13.950779 26380 ccl/streamingccl/streamproducer/event_stream.go:93 ⋮ [T1,Vsystem,n2,client=127.0.0.1:56462,hostssl,user=root] 783  starting physical replication event stream: tenant=10 initial_scan_timestamp=1710827892.699424453,0 previous_replicated_time=0,0
I240319 05:58:13.950848 26380 ccl/streamingccl/streamproducer/event_stream.go:140 ⋮ [T1,Vsystem,n2,client=127.0.0.1:56462,hostssl,user=root] 784  starting event stream with initial scan at 1710827892.699424453,0

But then we time out waiting to reach that initial scan timestamp:

I240319 05:58:16.915729 62 ccl/streamingccl/replicationtestutils/testutils.go:488 ⋮ [-] 821  SucceedsSoon: waiting for stream ingestion job progress 1710827890.000000000,0 to advance beyond 1710827892.699424453,0

That is odd in itself. But even more odd is the timestamp in our job progress. At least, it was odd to me until I remembered that we started quantising our checkpoints. My guess is we forgot to update this test.

[cockroach-teamcity]

ccl/streamingccl/streamingest.TestStreamingReplanOnLag failed on master @ f0116ea373a2b87155e7f0264df4f783ce177360:

=== RUN   TestStreamingReplanOnLag
    test_log_scope.go:170: test logs captured to: outputs.zip/logTestStreamingReplanOnLag964593691
    test_log_scope.go:81: use -show-logs to present logs inline
    testutils.go:488: condition failed to evaluate within 45s: from testutils.go:521: waiting for stream ingestion job progress 1710915230.000000000,0 to advance beyond 1710915230.064217292,0
    panic.go:626: -- test log scope end --
test logs left over in: outputs.zip/logTestStreamingReplanOnLag964593691
--- FAIL: TestStreamingReplanOnLag (53.39s)

Parameters:

• attempt=1
• run=1
• shard=15

Help

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

This test on roachdash | Improve this report!

[stevendanna]

@dt I downgraded this for now, but I think we skipped this after the quantization PR went in. I think some of your subsequent updates probably fixed this and we can unskip it now.