Flaky TestPartitionReader_Commit

[dimitarvdimitrov]

--- FAIL: TestPartitionReader_Commit (0.00s)
    --- FAIL: TestPartitionReader_Commit/commit_at_shutdown_doesn't_persist_if_we_haven't_consumed_any_records_since_startup (2.08s)
        logging.go:33: level info partition 1 msg starting consumption from partition start because no offset has been found start_offset -2 consumer_group test-group
        logging.go:33: level info partition 1 component kafka_client msg immediate metadata update triggered why querying metadata for consumer initialization
        logging.go:33: level info partition 1 target_lag 2s max_lag 15s msg partition reader is starting to consume partition until target and max consumer lag is honored
        logging.go:33: level info partition 1 component kafka_client msg assigning partitions why new assignments from direct consumer how assigning everything new, keeping current assignment input test[1{-2 e-1 ce0}]
        logging.go:33: level info partition 1 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
        logging.go:33: level info partition 1 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
        logging.go:33: level debug partition 1 msg last commit offset successfully committed to Kafka offset 1
        logging.go:33: level info partition 1 msg stopping partition reader
        logging.go:33: level info partition 1 msg starting consumption from last consumed offset last_consumed_offset 1 start_offset 2 consumer_group test-group
        logging.go:33: level info partition 1 component kafka_client msg immediate metadata update triggered why querying metadata for consumer initialization
        logging.go:33: level info partition 1 target_lag 2s max_lag 15s msg partition reader is starting to consume partition until target and max consumer lag is honored
        logging.go:33: level info partition 1 component kafka_client msg assigning partitions why new assignments from direct consumer how assigning everything new, keeping current assignment input test[1{2 e-1 ce0}]
        logging.go:33: level info partition 1 target_lag 2s max_lag 15s msg partition reader is consuming records to honor target and max consumer lag partition_start_offset 0 last_produced_offset 2
        logging.go:33: level info partition 1 target_lag 2s max_lag 15s msg partition reader consumed partition and current lag is lower than configured target consumer lag last_consumed_offset 2 current_lag 12.882613ms
        reader_test.go:1700: 
            	Error Trace:	/__w/mimir/mimir/pkg/storage/ingest/reader_test.go:1700
            	Error:      	Received unexpected error:
            	            	waiting for records: received 1, expected 0
            	Test:       	TestPartitionReader_Commit/commit_at_shutdown_doesn't_persist_if_we_haven't_consumed_any_records_since_startup
        logging.go:33: level info partition 1 msg stopping partition reader
        logging.go:33: level debug partition 1 msg last commit offset successfully committed to Kafka offset 2
        logging.go:33: level info partition 1 msg starting consumption from last consumed offset last_consumed_offset 2 start_offset 3 consumer_group test-group
        logging.go:33: level info partition 1 component kafka_client msg immediate metadata update triggered why querying metadata for consumer initialization
        logging.go:33: level info partition 1 target_lag 2s max_lag 15s msg partition reader is starting to consume partition until target and max consumer lag is honored
        logging.go:33: level info partition 1 component kafka_client msg assigning partitions why new assignments from direct consumer how assigning everything new, keeping current assignment input test[1{3 e-1 ce0}]
        logging.go:33: level info partition 1 target_lag 2s max_lag 15s msg partition reader is consuming records to honor target and max consumer lag partition_start_offset 0 last_produced_offset 2
        logging.go:33: level info partition 1 target_lag 2s max_lag 15s msg partition reader consumed partition and current lag is lower than configured target consumer lag last_consumed_offset 2 current_lag 3[71](https://github.com/grafana/mimir/actions/runs/9906769857/job/27369051204?pr=8695#step:8:72).913µs
        logging.go:33: level info partition 1 msg stopping partition reader
FAIL

[dimitarvdimitrov]

another instance albeit a different test case

--- FAIL: TestPartitionReader_Commit (0.00s)
    --- FAIL: TestPartitionReader_Commit/commit_at_shutdown (1.09s)
        logging.go:33: level info partition 1 msg starting consumption from partition start because no offset has been found start_offset -2 consumer_group test-group
        logging.go:33: level info partition 1 component kafka_client msg immediate metadata update triggered why querying metadata for consumer initialization
        logging.go:33: level info partition 1 target_lag 2s max_lag 15s msg partition reader is starting to consume partition until target and max consumer lag is honored
        logging.go:33: level info partition 1 component kafka_client msg assigning partitions why new assignments from direct consumer how assigning everything new, keeping current assignment input test[1{-2 e-1 ce0}]
        logging.go:33: level info partition 1 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
        logging.go:33: level info partition 1 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
        logging.go:33: level debug partition 1 msg last commit offset successfully committed to Kafka offset 1
        logging.go:33: level info partition 1 msg stopping partition reader
        logging.go:33: level info partition 1 msg starting consumption from last consumed offset last_consumed_offset 1 start_offset 2 consumer_group test-group
        logging.go:33: level info partition 1 component kafka_client msg immediate metadata update triggered why querying metadata for consumer initialization
        logging.go:33: level info partition 1 target_lag 2s max_lag 15s msg partition reader is starting to consume partition until target and max consumer lag is honored
        logging.go:33: level info partition 1 component kafka_client msg assigning partitions why new assignments from direct consumer how assigning everything new, keeping current assignment input test[1{2 e-1 ce0}]
        logging.go:33: level info partition 1 target_lag 2s max_lag 15s msg partition reader is consuming records to honor target and max consumer lag partition_start_offset 0 last_produced_offset 3
        logging.go:33: level info partition 1 target_lag 2s max_lag 15s msg partition reader consumed partition and current lag is lower than configured target consumer lag last_consumed_offset 3 current_lag 725.518µs
        reader_test.go:1673: 
            	Error Trace:	/__w/mimir/mimir/pkg/storage/ingest/reader_test.go:1673
            	Error:      	Received unexpected error:
            	            	waiting for records: received 2, expected 1
            	Test:       	TestPartitionReader_Commit/commit_at_shutdown
        logging.go:33: level info partition 1 msg stopping partition reader
        logging.go:33: level debug partition 1 msg last commit offset successfully committed to Kafka offset 3
FAIL
FAIL	github.com/grafana/mimir/pkg/storage/ingest	51.499s

[dimitarvdimitrov]

and another one

--- FAIL: TestPartitionReader_Commit (0.00s)
    --- FAIL: TestPartitionReader_Commit/commit_at_shutdown (1.05s)
        logger.go:29: 2024-09-20 18:41:50.305888963 +0000 UTC m=+19.877237574 level info partition 1 msg starting consumption from partition start because no offset has been found start_offset -2 consumer_group test-group
        logger.go:29: 2024-09-20 18:41:50.31198132 +0000 UTC m=+19.883329941 level info partition 1 component kafka_client msg immediate metadata update triggered why querying metadata for consumer initialization
        logger.go:29: 2024-09-20 18:41:50.317869313 +0000 UTC m=+19.889217925 level info partition 1 target_lag 2s max_lag 15s msg partition reader is starting to consume partition until target and max consumer lag is honored
        logger.go:29: 2024-09-20 18:41:50.318769419 +0000 UTC m=+19.890118040 level info partition 1 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:29: 2024-09-20 18:41:50.318830844 +0000 UTC m=+19.890179495 level info partition 1 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:29: 2024-09-20 18:41:50.3212365 +0000 UTC m=+19.892585121 level info partition 1 component kafka_client msg immediate metadata update triggered why from user ForceMetadataRefresh
        logger.go:29: 2024-09-20 18:41:50.321299939 +0000 UTC m=+19.892648550 level info partition 1 component kafka_client msg assigning partitions why new assignments from direct consumer how assigning everything new, keeping current assignment input test[1{-2 e-1 ce0}]
        reader_test.go:1926: 
            	Error Trace:	/__w/mimir/mimir/pkg/storage/ingest/reader_test.go:1926
            	Error:      	Received unexpected error:
            	            	waiting for records: received 0, expected 3
            	Test:       	TestPartitionReader_Commit/commit_at_shutdown
        logger.go:29: 2024-09-20 18:41:51.335780868 +0000 UTC m=+20.907129479 level info partition 1 msg stopping partition reader
caller=log.go:168 level=debug msg="fetched records" duration=5.896349ms start_offset=0 end_offset=2 asked_records=2 got_records=1 diff_records=1 asked_bytes=1000000 got_bytes=69 diff_bytes=999931 hwm=1 lso=0 err=null
caller=log.go:168 level=debug msg="received an error while fetching records; will retry after processing received records (if any)" duration=6.0[253](https://github.com/grafana/mimir/actions/runs/10964560175/job/30448442040?pr=9346#step:8:254)98ms start_offset=2 end_offset=4 asked_records=2 got_records=0 diff_records=2 asked_bytes=1000000 got_bytes=0 diff_bytes=1000000 hwm=0 lso=0 err="OFFSET_OUT_OF_RANGE: The requested offset is not within the range of offsets maintained by the server."
caller=log.go:168 level=debug msg="fetched records" duration=489.96µs start_offset=1 end_offset=2 asked_records=1 got_records=1 diff_records=0 asked_bytes=1000000 got_bytes=69 diff_bytes=999931 hwm=2 lso=0 err=null
caller=log.go:168 level=debug msg="received an error while fetching records; will retry after processing received records (if any)" duration=273.131µs start_offset=4 end_offset=6 asked_records=2 got_records=0 diff_records=2 asked_bytes=1000000 got_bytes=0 diff_bytes=1000000 hwm=2 lso=0 err="OFFSET_OUT_OF_RANGE: The requested offset is not within the range of offsets maintained by the server."
caller=log.go:168 level=debug msg="fetched records" duration=484.659848ms start_offset=4 end_offset=6 asked_records=2 got_records=0 diff_records=2 asked_bytes=1000000 got_bytes=0 diff_bytes=1000000 hwm=0 lso=0 err=null
caller=log.go:168 level=debug msg="fetched records" duration=581.385801ms start_offset=2 end_offset=4 asked_records=2 got_records=0 diff_records=2 asked_bytes=1000000 got_bytes=0 diff_bytes=1000000 hwm=0 lso=0 err=null
FAIL

[zenador]

Another instance: https://github.com/grafana/mimir/actions/runs/11098918635/job/30832351947?pr=9363

        reader_test.go:1962: 
            	Error Trace:	/__w/mimir/mimir/pkg/storage/ingest/reader_test.go:1962
            	Error:      	Received unexpected error:
            	            	waiting for records: received 1, expected 0
            	Test:       	TestPartitionReader_Commit/commit_at_shutdown_doesn't_persist_if_we_haven't_consumed_any_records_since_startup