Flaky TestIngester_PushToStorage_CircuitBreaker #9052
Description
The TestIngester_PushToStorage_CircuitBreaker test failed on the CI (for an unrelated PR).
@duricanikolic could you have a look if that's something obvious.
--- FAIL: TestIngester_PushToStorage_CircuitBreaker (4.01s)
--- FAIL: TestIngester_PushToStorage_CircuitBreaker/deadline_exceeded_with_initial_delay_enabled (2.00s)
logger.go:25: 2024-08-19 17:28:50.993596764 +0000 UTC m=+6.589185212 level warn msg -blocks-storage.backend=filesystem is for development and testing only; you should switch to an external object store for production use or use a shared filesystem
logger.go:25: 2024-08-19 17:28:50.996329099 +0000 UTC m=+6.591917547 level info msg TSDB idle compaction timeout set timeout 1h1m15.660357536s
logger.go:25: 2024-08-19 17:28:50.999902208 +0000 UTC m=+6.595490657 level info msg opening existing TSDBs
logger.go:25: 2024-08-19 17:28:51.003382648 +0000 UTC m=+6.598971096 level info component ingest_reader partition 0 msg starting consumption from partition start because no offset has been found start_offset -2 consumer_group ingester-zone-a-0
logger.go:25: 2024-08-19 17:28:51.005191734 +0000 UTC m=+6.600780183 level info component ingest_reader partition 0 component kafka_client msg immediate metadata update triggered why querying metadata for consumer initialization
logger.go:25: 2024-08-19 17:28:51.005773777 +0000 UTC m=+6.601362226 level info component ingest_reader partition 0 target_lag 2s max_lag 15s msg partition reader is starting to consume partition until target and max consumer lag is honored
logger.go:25: 2024-08-19 17:28:51.006917386 +0000 UTC m=+6.602505834 level info component ingest_reader partition 0 component kafka_client msg assigning partitions why new assignments from direct consumer how assigning everything new, keeping current assignment input mimir[0{-2 e-1 ce0}]
logger.go:25: 2024-08-19 17:28:51.008982868 +0000 UTC m=+6.604571316 level info component ingest_reader partition 0 target_lag 2s max_lag 15s msg partition reader found no records to consume because partition is empty partition_start_offset 0 last_produced_offset -1
logger.go:25: 2024-08-19 17:28:51.009052818 +0000 UTC m=+6.604641256 level info component ingest_reader partition 0 target_lag 2s max_lag 15s msg partition reader consumed partition and current lag is lower than configured target consumer lag last_consumed_offset -1 current_lag 0s
logger.go:25: 2024-08-19 17:28:51.009154226 +0000 UTC m=+6.604742675 level info msg not loading tokens from file, tokens file path is empty
logger.go:25: 2024-08-19 17:28:51.009228976 +0000 UTC m=+6.604817424 level info msg instance not found in ring, adding with no tokens ring ingester
logger.go:25: 2024-08-19 17:28:51.009721532 +0000 UTC m=+6.605309980 level info ring ingester-partitions msg partition not found in the ring partition 0
logger.go:25: 2024-08-19 17:28:51.010354871 +0000 UTC m=+6.605943309 level debug msg JoinAfter expired ring ingester
logger.go:25: 2024-08-19 17:28:51.010393844 +0000 UTC m=+6.605982291 level info msg auto-joining cluster after timeout ring ingester
logger.go:25: 2024-08-19 17:28:51.02603295 +0000 UTC m=+6.621621418 level info user test-0 msg Replaying on-disk memory mappable chunks if any
logger.go:25: 2024-08-19 17:28:51.026152943 +0000 UTC m=+6.621741382 level info user test-0 msg On-disk memory mappable chunks replay completed duration 7.043µs
logger.go:25: 2024-08-19 17:28:51.026207164 +0000 UTC m=+6.621795602 level info user test-0 msg Replaying WAL, this may take a while
logger.go:25: 2024-08-19 17:28:51.02690848 +0000 UTC m=+6.622497008 level info user test-0 msg WAL segment loaded segment 0 maxSegment 0
logger.go:25: 2024-08-19 17:28:51.026988408 +0000 UTC m=+6.622576847 level info user test-0 msg WAL replay completed checkpoint_replay_duration 121.376µs wal_replay_duration 617.149µs wbl_replay_duration 441ns chunk_snapshot_load_duration 0s mmap_chunk_replay_duration 7.043µs total_replay_duration 839.041µs
logger.go:25: 2024-08-19 17:28:51.085579958 +0000 UTC m=+6.681168416 level info user test-0 msg Compactions disabled
logger.go:25: 2024-08-19 17:28:51.085665838 +0000 UTC m=+6.681254286 level info user test-0 msg Running compaction after WAL replay
logger.go:25: 2024-08-19 17:28:51.085931743 +0000 UTC m=+6.681520190 level debug user test-0 caller ingester.go:1150 event acquired append lock
logger.go:25: 2024-08-19 17:28:51.085992696 +0000 UTC m=+6.681581144 level debug user test-0 caller ingester.go:1177 event got appender for timeseries series 1
logger.go:25: 2024-08-19 17:28:51.086173843 +0000 UTC m=+6.681762291 level debug user test-0 caller ingester.go:1197 event start commit succeededSamplesCount 1 failedSamplesCount 0 succeededExemplarsCount 0 failedExemplarsCount 0
logger.go:25: 2024-08-19 17:28:51.086477268 +0000 UTC m=+6.682065716 level debug user test-0 caller ingester.go:1212 event complete commit commitDuration 239.836µs
logger.go:25: 2024-08-19 17:28:51.107666471 +0000 UTC m=+6.703254939 level info user test-1 msg Replaying on-disk memory mappable chunks if any
logger.go:25: 2024-08-19 17:28:51.107761769 +0000 UTC m=+6.703350217 level info user test-1 msg On-disk memory mappable chunks replay completed duration 5.721µs
logger.go:25: 2024-08-19 17:28:51.107807354 +0000 UTC m=+6.703395792 level info user test-1 msg Replaying WAL, this may take a while
logger.go:25: 2024-08-19 17:28:51.108359671 +0000 UTC m=+6.703948129 level info user test-1 msg WAL segment loaded segment 0 maxSegment 0
logger.go:25: 2024-08-19 17:28:51.108419994 +0000 UTC m=+6.704008442 level info user test-1 msg WAL replay completed checkpoint_replay_duration 110.366µs wal_replay_duration 458.083µs wbl_replay_duration 361ns chunk_snapshot_load_duration 0s mmap_chunk_replay_duration 5.721µs total_replay_duration 659.898µs
logger.go:25: 2024-08-19 17:28:51.172896475 +0000 UTC m=+6.768484923 level info user test-1 msg Compactions disabled
logger.go:25: 2024-08-19 17:28:51.172993766 +0000 UTC m=+6.768582234 level info user test-1 msg Running compaction after WAL replay
logger.go:25: 2024-08-19 17:28:51.173249101 +0000 UTC m=+6.768837589 level debug user test-1 caller ingester.go:1150 event acquired append lock
logger.go:25: 2024-08-19 17:28:51.173308251 +0000 UTC m=+6.768896730 level debug user test-1 caller ingester.go:1177 event got appender for timeseries series 1
logger.go:25: 2024-08-19 17:28:51.173605405 +0000 UTC m=+6.769193852 level debug user test-1 caller ingester.go:1197 event start commit succeededSamplesCount 1 failedSamplesCount 0 succeededExemplarsCount 0 failedExemplarsCount 0
logger.go:25: 2024-08-19 17:28:51.17388216 +0000 UTC m=+6.769470607 level debug user test-1 caller ingester.go:1212 event complete commit commitDuration 193.951µs
logger.go:25: 2024-08-19 17:28:51.174030906 +0000 UTC m=+6.769619354 level debug user test-1 caller ingester.go:1150 event acquired append lock
logger.go:25: 2024-08-19 17:28:51.174150248 +0000 UTC m=+6.769738686 level debug user test-1 caller ingester.go:1177 event got appender for timeseries series 1
logger.go:25: 2024-08-19 17:28:51.174228354 +0000 UTC m=+6.769816802 level debug user test-1 caller ingester.go:1197 event start commit succeededSamplesCount 1 failedSamplesCount 0 succeededExemplarsCount 0 failedExemplarsCount 0
logger.go:25: 2024-08-19 17:28:51.174365719 +0000 UTC m=+6.769954167 level debug user test-1 caller ingester.go:1212 event complete commit commitDuration 65.683µs
logger.go:25: 2024-08-19 17:28:51.188905688 +0000 UTC m=+6.784494157 level info user test-2 msg Replaying on-disk memory mappable chunks if any
logger.go:25: 2024-08-19 17:28:51.188991959 +0000 UTC m=+6.784580397 level info user test-2 msg On-disk memory mappable chunks replay completed duration 5.661µs
logger.go:25: 2024-08-19 17:28:51.189042353 +0000 UTC m=+6.784630801 level info user test-2 msg Replaying WAL, this may take a while
logger.go:25: 2024-08-19 17:28:51.189747174 +0000 UTC m=+6.785335623 level info user test-2 msg WAL segment loaded segment 0 maxSegment 0
logger.go:25: 2024-08-19 17:28:51.189812065 +0000 UTC m=+6.785400513 level info user test-2 msg WAL replay completed checkpoint_replay_duration 112.71µs wal_replay_duration 615.295µs wbl_replay_duration 320ns chunk_snapshot_load_duration 0s mmap_chunk_replay_duration 5.661µs total_replay_duration 820.698µs
logger.go:25: 2024-08-19 17:28:51.239193683 +0000 UTC m=+6.834782141 level info user test-2 msg Compactions disabled
logger.go:25: 2024-08-19 17:28:51.239314057 +0000 UTC m=+6.834902505 level info user test-2 msg Running compaction after WAL replay
logger.go:25: 2024-08-19 17:28:51.239668116 +0000 UTC m=+6.835256574 level debug user test-2 caller ingester.go:1150 event acquired append lock
logger.go:25: 2024-08-19 17:28:51.239742294 +0000 UTC m=+6.835330742 level debug user test-2 caller ingester.go:1177 event got appender for timeseries series 1
logger.go:25: 2024-08-19 17:28:51.240037874 +0000 UTC m=+6.835626322 level debug user test-2 caller ingester.go:1197 event start commit succeededSamplesCount 1 failedSamplesCount 0 succeededExemplarsCount 0 failedExemplarsCount 0
logger.go:25: 2024-08-19 17:28:51.240320329 +0000 UTC m=+6.835908768 level debug user test-2 caller ingester.go:1212 event complete commit commitDuration 208.789µs
logger.go:25: 2024-08-19 17:28:51.240453778 +0000 UTC m=+6.836042226 level debug user test-2 caller ingester.go:1150 event acquired append lock
logger.go:25: 2024-08-19 17:28:51.24052462 +0000 UTC m=+6.836113068 level debug user test-2 caller ingester.go:1177 event got appender for timeseries series 1
logger.go:25: 2024-08-19 17:28:51.240584742 +0000 UTC m=+6.836173190 level debug user test-2 caller ingester.go:1197 event start commit succeededSamplesCount 1 failedSamplesCount 0 succeededExemplarsCount 0 failedExemplarsCount 0
logger.go:25: 2024-08-19 17:28:51.240823576 +0000 UTC m=+6.836412024 level debug user test-2 caller ingester.go:1212 event complete commit commitDuration 73.677µs
circuitbreaker_test.go:562:
Error Trace: /__w/mimir/mimir/pkg/ingester/circuitbreaker_test.go:562
Error: Received unexpected error:
Diff:
--- metric output does not match expectation; want
+++ got:
@@ -7,3 +7,3 @@
# TYPE cortex_ingester_circuit_breaker_request_timeouts_total counter
-cortex_ingester_circuit_breaker_request_timeouts_total{request_type="push"} 0
+cortex_ingester_circuit_breaker_request_timeouts_total{request_type="push"} 1
# HELP cortex_ingester_circuit_breaker_results_total Results of executing requests via the circuit breaker.
@@ -11,3 +11,3 @@
cortex_ingester_circuit_breaker_results_total{request_type="push",result="circuit_breaker_open"} 0
-cortex_ingester_circuit_breaker_results_total{request_type="push",result="error"} 0
+cortex_ingester_circuit_breaker_results_total{request_type="push",result="error"} 1
cortex_ingester_circuit_breaker_results_total{request_type="push",result="success"} 0
Test: TestIngester_PushToStorage_CircuitBreaker/deadline_exceeded_with_initial_delay_enabled
logger.go:25: 2024-08-19 17:28:51.269691099 +0000 UTC m=+6.865279557 level info ring ingester-partitions msg partition ring lifecycler is shutting down ring ingester-partitions
logger.go:25: 2024-08-19 17:28:51.269891302 +0000 UTC m=+6.865479740 level info component ingest_reader partition 0 msg stopping partition reader
logger.go:25: 2024-08-19 17:28:51.271107906 +0000 UTC m=+6.866696354 level info msg lifecycler loop() exited gracefully ring ingester
logger.go:25: 2024-08-19 17:28:51.271166755 +0000 UTC m=+6.866755204 level info msg changing instance state from old_state ACTIVE new_state LEAVING ring ingester
logger.go:25: 2024-08-19 17:28:51.271310954 +0000 UTC m=+6.866899402 level info msg transfers are disabled
logger.go:25: 2024-08-19 17:28:51.2713735 +0000 UTC m=+6.866961948 level info msg lifecycler entering final sleep before shutdown final_sleep 0s
logger.go:25: 2024-08-19 17:28:51.271411822 +0000 UTC m=+6.867000269 level debug msg unregistering instance from ring ring ingester
logger.go:25: 2024-08-19 17:28:51.271520173 +0000 UTC m=+6.867108611 level info msg instance removed from the KV store ring ingester
level=info msg="uploading new block to long-term storage" block=00000000010000000000000000
level=debug msg="uploaded file" from=/tmp/TestShipper_DeceivingUploadErrors2380332338/001/00000000010000000000000000/index dst=00000000010000000000000000/index bucket="fs: /tmp/TestShipper_DeceivingUploadErrors2380332338/002"
level=error msg="uploading new block to long-term storage failed" block=00000000010000000000000000 err="upload meta file: base name matches, will fail upload"
FAIL
FAIL github.com/grafana/mimir/pkg/ingester 588.261s