ClickHouse / ClickHouse/ClickHouse
ClickHouse deduplicated a part that was declared 'lost forever' a minute ago
- Dominant language
- C++
- Stars
- 49.9k
- Forks
- 9k
- Avg merge
- 21h 32m
- Merged PRs (30d)
- 515
Description
I ran into this on 23.4, but I haven't found any related fixes since then.
**Describe what's wrong**
```
--- Replica1 was running an insert and had just created 20230926_14377_14377_0 when a hardware failure happened.
--- Replica2 started downloading 20230926_14377_14377_0
2023.09.27 03:43:24.671321 [ 1687139 ] {} db.shard (dd2e9c2e-9fe9-4211-a471-4f134a57f382) (Fetcher): Downloading part 20230926_14377_14377_0 onto disk default.
--- Replica1 disappeared
--- Replica2 failed to download 20230926_14377_14377_0
2023.09.27 03:46:25.397737 [ 1687139 ] {} db.shard (dd2e9c2e-9fe9-4211-a471-4f134a57f382): auto DB::StorageReplicatedMergeTree::processQueueEntry(ReplicatedMergeTreeQueue::SelectedEntryPtr)::(anonymous class)::operator()(DB::StorageReplicatedMergeTree::LogEntryPtr &) const: Code: 23. DB::Exception: Cannot read from istream at offset 31457280. (CANNOT_READ_FROM_ISTREAM), Stack trace (when copying this message, always include the lines below):
--- Replica2 was trying to find the missing part while Replica1 was unavailable
2023.09.27 03:46:27.309924 [ 1687077 ] {} db.shard (ReplicatedMergeTreePartCheckThread): Checking part 20230926_14377_14377_0
2023.09.27 03:46:27.309939 [ 1687119 ] {} db.shard (dd2e9c2e-9fe9-4211-a471-4f134a57f382): Code: 234. DB::Exception: No active replica has part 20230926_14377_14377_0 or covering part (cannot execute queue-0003490511: GET_PART with virtual parts [20230926_14377_14377_0]). (NO_REPLICA_HAS_PART)
2023.09.27 03:46:27.335015 [ 1687077 ] {} db.shard (ReplicatedMergeTreePartCheckThread): Part 20230926_14377_14377_0 in zookeeper: false, locally: false
2023.09.27 03:46:27.335024 [ 1687077 ] {} db.shard (ReplicatedMergeTreePartCheckThread): Checking if anyone has a part 20230926_14377_14377_0 or covering part.
2023.09.27 03:46:27.413211 [ 1687077 ] {} db.shard (ReplicatedMergeTreePartCheckThread): Found the missing part 20230926_14377_14377_0 at 20230926_14377_14377_0 on Replica1
...
--- Replica1 came back without 20230926_14377_14377_0
2023.09.27 05:07:02.710164 [ 3103 ] {} db.shard (ReplicatedMergeTreeQueue): Insert entry queue-0003493468 to queue with type GET_PART with virtual parts [20230926_14377_14377_0]
--- Replica2 declared that 20230926_14377_14377_0 is 'lost forever' and replaced it with an empty part
2023.09.27 05:07:03.285153 [ 1686997 ] {} db.shard (ReplicatedMergeTreePartCheckThread): Checking part 20230926_14377_14377_0
2023.09.27 05:07:03.318694 [ 1686997 ] {} db.shard (ReplicatedMergeTreePartCheckThread): Part 20230926_14377_14377_0 in zookeeper: false, locally: false
2023.09.27 05:07:03.318715 [ 1686997 ] {} db.shard (ReplicatedMergeTreePartCheckThread): Checking if anyone has a part 20230926_14377_14377_0 or covering part.
2023.09.27 05:07:03.452286 [ 1686997 ] {} db.shard (ReplicatedMergeTreePartCheckThread): No replica has part covering 20230926_14377_14377_0 and a merge is impossible: we didn't find smaller parts with either the same min block or the same max block.
2023.09.27 05:07:03.452314 [ 1686997 ] {} db.shard (dd2e9c2e-9fe9-4211-a471-4f134a57f382): Going to replace lost part 20230926_14377_14377_0 with empty part
2023.09.27 05:07:03.452760 [ 1686997 ] {} db.shard (dd2e9c2e-9fe9-4211-a471-4f134a57f382): Trying to reserve 1.00 MiB using storage policy from min volume index 0
2023.09.27 05:07:03.452777 [ 1686997 ] {} DiskLocal: Reserved 1.00 MiB on local disk `default`, having unreserved 23.50 TiB.
2023.09.27 05:07:03.477406 [ 1686997 ] {} MergedBlockOutputStream: filled checksums 20230926_14377_14377_0 (state Temporary)
2023.09.27 05:07:03.483133 [ 1686997 ] {} db.shard (dd2e9c2e-9fe9-4211-a471-4f134a57f382): Renaming temporary part tmp_empty_20230926_14377_14377_0 to 20230926_14377_14377_0 with tid (1, 1, 00000000-0000-0000-0000-000000000000).
2023.09.27 05:07:03.880842 [ 1686997 ] {} db.shard (dd2e9c2e-9fe9-4211-a471-4f134a57f382): Created empty part 20230926_14377_14377_0 instead of lost part
2023.09.27 05:07:03.880875 [ 1686997 ] {} db.shard (ReplicatedMergeTreePartCheckThread): Part 20230926_14377_14377_0 is lost forever.
--- Replica1 downloaded the empty 20230926_14377_14377_0 from Replica2
2023.09.27 05:07:04.871465 [ 3151 ] {} db.shard (150ee15b-b248-496b-aa4a-37a362f9ffeb): Fetching part 20230926_14377_14377_0 from /clickhouse/oDSP/tables/6/dsp_fact_event1/replicas/Replica2
2023.09.27 05:07:04.974022 [ 3151 ] {} db.shard (150ee15b-b248-496b-aa4a-37a362f9ffeb): Fetched part 20230926_14377_14377_0 from /clickhouse/oDSP/tables/6/dsp_fact_event1/replicas/Replica2
--- Replica2 scheduled a merge with the empty 20230926_14377_14377_0
2023.09.27 05:07:07.110135 [ 1686964 ] {} db.shard (dd2e9c2e-9fe9-4211-a471-4f134a57f382): Created log entry /clickhouse/oDSP/tables/6/dsp_fact_event1/log/log-0004992541 for merge 20230926_14334_14502_3
--- Replica1 tried to drop the empty 20230926_14377_14377_0 but couldn't
2023.09.27 05:07:36.283336 [ 3085 ] {} db.shard (150ee15b-b248-496b-aa4a-37a362f9ffeb): Will drop empty part 20230926_14377_14377_0
2023.09.27 05:07:36.283369 [ 3085 ] {} db.shard (150ee15b-b248-496b-aa4a-37a362f9ffeb): Will try to insert a log entry to DROP_PART for part 20230926_14377_14377_0
--- The failed insert was repeated but Replica1 deduplicated the lost block
2023.09.27 05:08:22.171703 [ 3419 ] {3c2d4473-6b95-4a61-8007-a2729eec54eb} db.shard (150ee15b-b248-496b-aa4a-37a362f9ffeb) (Replicated OutputStream): Wrote block with ID '20230926_10703683689539136913_12924837775908651131', 43724 rows
2023.09.27 05:08:22.184893 [ 3419 ] {3c2d4473-6b95-4a61-8007-a2729eec54eb} createEphemeralLockInZooKeeper: Deduplication path already exists: deduplication_path=/clickhouse/tables/6/event1/blocks/20230926_10703683689539136913_12924837775908651131
2023.09.27 05:08:22.186857 [ 3419 ] {3c2d4473-6b95-4a61-8007-a2729eec54eb} db.shard (150ee15b-b248-496b-aa4a-37a362f9ffeb) (Replicated OutputStream): Block with ID 20230926_10703683689539136913_12924837775908651131 already exists locally as part 20230926_14377_14377_0; ignoring it.
```
**Expected behavior**
It would be great if ClickHouse removed the block from the deduplicating list when it declared that the part is lost forever
Contributor guide
Assessment
This issue has not been assessed yet.