Skip to content

Table restore failed because tmp_restore_xxxx part was cleaned up (in test 03032_async_backup_restore) #67220

Closed
#67491
Closed
Table restore failed because tmp_restore_xxxx part was cleaned up (in test 03032_async_backup_restore)#67220
#67491
Assignees
vitlibar
Labels
bugConfirmed user-visible misbehaviour in official releasetestingSpecial issue with list of bugs found by CI
@davenger

Description

@davenger
davenger
opened on Jul 26, 2024

Happened in CI run:
https://s3.amazonaws.com/clickhouse-test-reports/67176/498ae4358647dbff5fde2861a7113a9c9597930a/stateless_tests__debug__s3_storage__[2_2].html

https://pastila.nl/?000628ea/0cc76ddc1362172872c6875d86f3bcd2#e8Bk2B6g6cTnEdomCgRz2A==

In the logs I see that table tbl2 was created by restore

2024.07.26 11:21:51.508938 [ 33898 ] {06b2a03a-4430-4d2a-92e7-fdf12b4fbfaf} <Trace> RestorerFromBackup: Creating table test_xrb1u51c.tbl2: CREATE TABLE IF NOT EXISTS test_xrb1u51c.tbl2 UU
ID '585d5243-2829-4c58-be87-2fdc8e2b61e5' (`a` Int32) ENGINE = MergeTree ORDER BY tuple() SETTINGS index_granularity = 31030, min_bytes_for_wide_part = 0, ratio_of_defaults_for_sparse_ser
ialization = 0.8355984687805176, replace_long_file_name_to_hash = true, max_file_name_length = 11, min_bytes_for_full_part_storage = 536870912, compact_parts_max_bytes_to_buffer = 1950487
17, compact_parts_max_granules_to_buffer = 256, compact_parts_merge_max_bytes_to_prefetch_part = 18185723, merge_max_block_size = 7862, old_parts_lifetime = 480., prefer_fetch_merged_part
_size_threshold = 10737418240, vertical_merge_algorithm_min_rows_to_activate = 1000000, vertical_merge_algorithm_min_columns_to_activate = 33, min_merge_bytes_to_use_direct_io = 461731536
8, index_granularity_bytes = 23848274, concurrent_part_removal_threshold = 100, allow_vertical_merges_from_compact_to_wide_parts = true, cache_populated_by_fetch = true, marks_compress_bl
ock_size = 96071, primary_key_compress_block_size = 30522
2024.07.26 11:21:51.571949 [ 33898 ] {06b2a03a-4430-4d2a-92e7-fdf12b4fbfaf} <Debug> test_xrb1u51c.tbl2 (585d5243-2829-4c58-be87-2fdc8e2b61e5): Loading data parts
2024.07.26 11:21:51.575299 [ 33898 ] {06b2a03a-4430-4d2a-92e7-fdf12b4fbfaf} <Debug> test_xrb1u51c.tbl2 (585d5243-2829-4c58-be87-2fdc8e2b61e5): There are no data parts
2024.07.26 11:21:51.575644 [ 33898 ] {06b2a03a-4430-4d2a-92e7-fdf12b4fbfaf} <Debug> DatabaseAtomic (test_xrb1u51c): There are 0 detached tables. Start searching non used tables.
2024.07.26 11:21:51.575670 [ 33898 ] {06b2a03a-4430-4d2a-92e7-fdf12b4fbfaf} <Debug> DatabaseAtomic (test_xrb1u51c): Found 0 non used tables in detached tables.
2024.07.26 11:21:51.578000 [ 33385 ] {06b2a03a-4430-4d2a-92e7-fdf12b4fbfaf} <Trace> BackupReaderDisk: Copying file data/test_xrb1u51c/tbl/all_1_1_0/a.bin to disk s3 through buffers
2024.07.26 11:21:51.652605 [ 33385 ] {06b2a03a-4430-4d2a-92e7-fdf12b4fbfaf} <Trace> BackupReaderDisk: Copying file data/test_xrb1u51c/tbl/all_1_1_0/a.cmrk2 to disk s3 through buffers
2024.07.26 11:21:51.718474 [ 87668 ] {} <Debug> TCPHandler: Connected ClickHouse client version 24.8.0, revision: 54468, database: test_xrb1u51c, user: default.
2024.07.26 11:21:51.722464 [ 33385 ] {06b2a03a-4430-4d2a-92e7-fdf12b4fbfaf} <Trace> BackupReaderDisk: Copying file data/test_xrb1u51c/tbl/all_1_1_0/checksums.txt to disk s3 through buffer
s
2024.07.26 11:21:51.774745 [ 33385 ] {06b2a03a-4430-4d2a-92e7-fdf12b4fbfaf} <Trace> BackupReaderDisk: Copying file data/test_xrb1u51c/tbl/all_1_1_0/columns.txt to disk s3 through buffers
2024.07.26 11:21:51.799616 [ 33385 ] {06b2a03a-4430-4d2a-92e7-fdf12b4fbfaf} <Trace> BackupReaderDisk: Copying file data/test_xrb1u51c/tbl/all_1_1_0/count.txt to disk s3 through buffers
2024.07.26 11:21:51.830418 [ 33385 ] {06b2a03a-4430-4d2a-92e7-fdf12b4fbfaf} <Trace> BackupReaderDisk: Copying file data/test_xrb1u51c/tbl/all_1_1_0/default_compression_codec.txt to disk s
3 through buffers
2024.07.26 11:21:51.872196 [ 33385 ] {06b2a03a-4430-4d2a-92e7-fdf12b4fbfaf} <Trace> BackupReaderDisk: Copying file data/test_xrb1u51c/tbl/all_1_1_0/metadata_version.txt to disk s3 through
 buffers
2024.07.26 11:21:52.275425 [ 33385 ] {06b2a03a-4430-4d2a-92e7-fdf12b4fbfaf} <Trace> BackupReaderDisk: Copying file data/test_xrb1u51c/tbl/all_1_1_0/serialization.json to disk s3 through b
uffers
2024.07.26 11:21:52.277060 [ 20950 ] {} <Debug> TCPHandler: Connected ClickHouse client version 24.8.0, revision: 54468, database: test_xrb1u51c, user: default.
2024.07.26 11:21:53.033646 [ 87668 ] {} <Debug> TCPHandler: Connected ClickHouse client version 24.8.0, revision: 54468, database: test_xrb1u51c, user: default.
2024.07.26 11:21:53.376399 [ 87671 ] {} <Debug> TCPHandler: Connected ClickHouse client version 24.8.0, revision: 54468, database: test_xrb1u51c, user: default.
2024.07.26 11:21:54.500098 [ 87231 ] {} <Debug> TCPHandler: Connected ClickHouse client version 24.8.0, revision: 54468, database: test_xrb1u51c, user: default.
2024.07.26 11:21:54.959037 [ 87739 ] {} <Debug> TCPHandler: Connected ClickHouse client version 24.8.0, revision: 54468, database: test_xrb1u51c, user: default.
2024.07.26 11:21:55.340825 [ 87739 ] {} <Debug> TCPHandler: Connected ClickHouse client version 24.8.0, revision: 54468, database: test_xrb1u51c, user: default.
2024.07.26 11:21:55.849328 [ 87739 ] {} <Debug> TCPHandler: Connected ClickHouse client version 24.8.0, revision: 54468, database: test_xrb1u51c, user: default.
2024.07.26 11:21:56.351297 [ 87739 ] {} <Debug> TCPHandler: Connected ClickHouse client version 24.8.0, revision: 54468, database: test_xrb1u51c, user: default.
2024.07.26 11:21:56.858393 [ 87739 ] {} <Debug> TCPHandler: Connected ClickHouse client version 24.8.0, revision: 54468, database: test_xrb1u51c, user: default.

And suddenly the part that is being restored got cleaned up:

2024.07.26 11:21:57.084977 [ 1612 ] {} <Warning> test_xrb1u51c.tbl2 (585d5243-2829-4c58-be87-2fdc8e2b61e5): Removing temporary directory /var/lib/clickhouse/disks/s3/store/585/585d5243-2829-4c58-be87-2fdc8e2b61e5/tmp_restore_all_1_1_0-192d2bf6-0929-4b3e-b54a-c3e2f78a27a0/
2024.07.26 11:21:57.085034 [ 1612 ] {} <Warning> test_xrb1u51c.tbl2 (585d5243-2829-4c58-be87-2fdc8e2b61e5): Since zero-copy replication is enabled we are not going to remove blobs from shared storage for /var/lib/clickhouse/disks/s3/store/585/585d5243-2829-4c58-be87-2fdc8e2b61e5/tmp_restore_all_1_1_0-192d2bf6-0929-4b3e-b54a-c3e2f78a27a0/

And restore failed

2024.07.26 11:21:57.667618 [ 33385 ] {06b2a03a-4430-4d2a-92e7-fdf12b4fbfaf} <Error> test_xrb1u51c.tbl2 (585d5243-2829-4c58-be87-2fdc8e2b61e5): Part /var/lib/clickhouse/disks/s3/store/585/585d5243-2829-4c58-be87-2fdc8e2b61e5/tmp_restore_all_1_1_0-192d2bf6-0929-4b3e-b54a-c3e2f78a27a0/ is broken and needs manual correction
2024.07.26 11:21:57.667730 [ 33385 ] {06b2a03a-4430-4d2a-92e7-fdf12b4fbfaf} <Error> test_xrb1u51c.tbl2 (585d5243-2829-4c58-be87-2fdc8e2b61e5): Failed to restore part all_1_1_0 because it's broken. You can skip broken parts while restoring by setting 'restore_broken_parts_as_detached = true'
2024.07.26 11:21:57.708863 [ 33898 ] {} <Error> BackupsWorker: Failed to restore from backup Disk('backups', '03032_async_backup_restore_test_xrb1u51c'): Code: 107. DB::ErrnoException: Cannot open file /var/lib/clickhouse/disks/s3/store/585/585d5243-2829-4c58-be87-2fdc8e2b61e5/tmp_restore_all_1_1_0-192d2bf6-0929-4b3e-b54a-c3e2f78a27a0/a.bin: , errno: 2, strerror: No such file or directory: columns: columns format version: 1

Metadata

Metadata

Assignees

Labels

bugConfirmed user-visible misbehaviour in official releasetestingSpecial issue with list of bugs found by CI

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions