Why is consistency check removing all entries from the cbbackup database?

Britt_Burnett · May 22, 2024, 9:23am

I had scheduled consistency checks to run on an AWS S3 bucket weekly. I didn’t notice for two weeks until my S3 storage ballooned to 3 times the size it had been previously.

After researching, it looks like when the scheduled consistency check ran for the first time, it cleared all entries from the local database. The next time the backup ran, it uploaded the same files that were already in S3 storage. The next week the scheduled consistency check ran and the same thing happened. I synchronized the repository to S3 and confirmed duplicate file name entries in the cloud_files and cloud_file_versions tables. The data is indeed duplicated in S3.

I manually cleaned up the duplicate entries in S3 using an inventory report to remove objects uploaded on dates the backups ran after the consistency check. Then I synchronized the repository, which sync’d the local database to the S3 bucket.

Then I backed up the database to have a rollback option and manually ran a consistency check. The local database was cleared again. Below are sample entries from the logs.

There are thousands of these entry types. I’ve confirmed the file is stored in the S3 but I have not researched to determine the file details to try to map the data back to the cbb repository.

2024-05-21 09:57:28,211 [PL] [5] WARN - all: Cannot convert string ‘CBB_Archive\dell5810-standard-ia\ECBB_DELL5810\zzzz27ppn4tencbgnnk5jr4jvejxibleqo4ohwvspinneuuwvyaml6jops5hxkuq73sfxzhj65ipyuf2xna4zf64c66qmatma7fz74z4ghzclacv5ixvzgrwe3pnkbazob52v4g5vfar36pe23fszf46ojamif7y3xwbrznoni2mbpotywha====’ to storage path

There are also thousands of these entry types:

2024-05-21 10:51:09,632 [PL] [1] WARN - File ECBB_DELL5810/xsmrclcce6st5pj2lhc6t74nyt2skrhpipqhoqnx533ijgvurus3t2xzbvkfcfjdx32eehzrz54pf24em4cp3wc2haxzodhz44oint5zmqkhxlejb2ht7lxk2zhhkhgmw3aj2sk63swnei3p5kxxi64cctgo5oxp3ebhszo7rkssvosjqz7dky7xmunldti4st5wnkblxkrjy=== will be ignored. History path:

This appears to be the beginning of the process to clear the local db:

2024-05-21 09:57:29,950 [PL] [5] NOTICE - ArchiveLiteSyncHelper.CommitSync: Start commiting sync changes…
2024-05-21 09:57:29,963 [PL] [5] NOTICE - ArchiveLiteSyncHelper.CheckRestorePointsIntegrity: Start check restore points integrity…
2024-05-21 09:57:29,973 [PL] [5] NOTICE - ArchiveLiteSyncHelper.RemovingMissingGenerations: Start removing missing generations…
2024-05-21 09:57:29,990 [PL] [5] NOTICE - ArchiveLiteSyncHelper.RemovingMissingRestorePoints: Start removing the missing restore points…
2024-05-21 09:57:29,995 [PL] [5] NOTICE - ArchiveLiteSyncHelper.RemoveMissingStorageFiles: Start removing the missing storage files…
2024-05-21 09:57:30,001 [PL] [5] NOTICE - ArchiveLiteSyncHelper.ClearDeduplicationDatabaseIfGenerationChanged: Start cleaning deduplication databases…
2024-05-21 09:57:30,006 [PL] [5] NOTICE - ArchiveLiteSyncHelper.SetToPurgeFilesAlreadyBeenPurged: Start setting to purge state files already marked as purged…
2024-05-21 09:57:30,014 [PL] [5] NOTICE - ArchiveLiteSyncHelper.SetFinishedDateToRestorePointsWithoutIt: Start setting finish date to restore points without it…
2024-05-21 09:57:30,022 [PL] [5] NOTICE - ArchiveLiteSyncHelper.ExecuteCompleteConsistencyCheck: Start executing total consistency check…
2024-05-21 09:57:30,026 [PL] [5] NOTICE - ArchiveLiteSyncHelper.CommitSync: Committing sync changes complete…
2024-05-21 09:59:13,694 [PL] [13] NOTICE - SQL query ‘DELETE FROM cloud_file_versions WHERE file_id IN (SELECT id FROM cloud_files WHERE destination_id = ?)’. Parameters: ‘[param_1]=‘1001’’ takes in total: 00:01:03
2024-05-21 10:01:07,123 [PL] [13] NOTICE - SQL query ‘DELETE FROM cloud_files WHERE destination_id = ?’. Parameters: ‘[param_1]=‘1001’’ takes in total: 00:01:53
2024-05-21 10:01:12,681 [PL] [13] NOTICE - Sync for ‘AmazonS3-Dell5810-Standard-IA-US-East-Ohio’ is completed. Files: 492046, size: 1.66 TB, duration: 01:22:11
2024-05-21 10:01:12,866 [PL] [13] WARN - Cannot generate entries because UpdateMutexLockName is Acquired
2024-05-21 10:03:11,559 [PL] [20] NOTICE - set default ssl to False

Then another final process at the end of the process

2024-05-21 10:54:21,442 [PL] [12] NOTICE - ArchiveLiteSyncHelper.CommitSync: Start commiting sync changes…
2024-05-21 10:54:21,450 [PL] [12] NOTICE - ArchiveLiteSyncHelper.CheckRestorePointsIntegrity: Start check restore points integrity…
2024-05-21 10:54:21,459 [PL] [12] NOTICE - ArchiveLiteSyncHelper.RemovingMissingGenerations: Start removing missing generations…
2024-05-21 10:54:21,474 [PL] [12] NOTICE - ArchiveLiteSyncHelper.RemovingMissingRestorePoints: Start removing the missing restore points…
2024-05-21 10:54:21,479 [PL] [12] NOTICE - ArchiveLiteSyncHelper.RemoveMissingStorageFiles: Start removing the missing storage files…
2024-05-21 10:54:21,482 [PL] [12] NOTICE - ArchiveLiteSyncHelper.ClearDeduplicationDatabaseIfGenerationChanged: Start cleaning deduplication databases…
2024-05-21 10:54:21,488 [PL] [12] NOTICE - ArchiveLiteSyncHelper.SetToPurgeFilesAlreadyBeenPurged: Start setting to purge state files already marked as purged…
2024-05-21 10:54:21,494 [PL] [12] NOTICE - ArchiveLiteSyncHelper.SetFinishedDateToRestorePointsWithoutIt: Start setting finish date to restore points without it…
2024-05-21 10:54:21,500 [PL] [12] NOTICE - ArchiveLiteSyncHelper.ExecuteCompleteConsistencyCheck: Start executing total consistency check…
2024-05-21 10:54:21,506 [PL] [12] NOTICE - ArchiveLiteSyncHelper.CommitSync: Committing sync changes complete…
2024-05-21 10:54:21,602 [SERV] [1] WARN - Folder is missing in backup storage: c:
2024-05-21 10:54:22,000 [SERV] [1] WARN - Folder is missing in backup storage: d:
2024-05-21 10:56:28,070 [SERV] [1] WARN - Folder is missing in backup storage: cbb_configuration
2024-05-21 10:58:40,331 [PL] [1] NOTICE - SQL query ‘DELETE FROM cloud_files WHERE destination_id = ?’. Parameters: ‘[param_1]=‘1001’’ takes in total: 00:01:17
2024-05-21 11:00:01,851 [PL] [1] NOTICE - Sync for ‘AmazonS3-Dell5810-Standard-IA-US-East-Ohio’ is completed. Files: 0, size: 0 bytes, duration: 00:58:46
2024-05-21 11:00:01,869 [PL] [1] ERROR - Consistency check found some differences; Code - 1016
2024-05-21 11:00:01,905 [SERV] [1] NOTICE - Total (info messages, warnings, errors): 1
2024-05-21 11:00:01,951 [SERV] [1] NOTICE - Total (info messages, warnings, errors): 1
2024-05-21 11:00:01,967 [PL] [1] ERROR - Consistency check found some differences (Code: 1016)
Description: Consistency check has detected differences

2024-05-21 11:00:02,571 [SERV] [1] NOTICE - =
2024-05-21 11:00:02,609 [SERV] [1] NOTICE - Starting (Running) / 01:02:32 /
2024-05-21 11:00:02,719 [SERV] [1] NOTICE - Total: (Total) / 01:02:32 /
2024-05-21 11:00:02,729 [SERV] [1] NOTICE - =
2024-05-21 11:00:02,744 [SERV] [1] NOTICE - Plan status: Fail. Elapsed time: 01:02:32.3865940. Version: 7.9.4.103
2024-05-21 11:00:02,765 [SERV] [1] NOTICE - Elapsed time: 02:20:06. Max memory usage: 1.07 GB. Processor time: 00:12:28. DB connection: 26188 DB query: 526974 Status report: 3634
2024-05-21 11:00:02,772 [SERV] [1] NOTICE - IO stats: read bytes: 12944540478, write bytes: 4729263372, other bytes: 157530850, reads: 12685665, writes: 5748019, other ops: 2795980
2024-05-21 11:00:02,782 [SERV] [1] NOTICE - Top long queries:
2024-05-21 11:00:02,810 [SERV] [1] NOTICE - “UPDATE cloud_files SET destination_id = ? WHERE destination_id = ?”. Count: 1. Total time: 114.23
2024-05-21 11:00:02,826 [SERV] [1] NOTICE - “DELETE FROM cloud_files WHERE destination_id = ?”. Count: 1. Total time: 77.31
2024-05-21 11:00:02,854 [SERV] [1] NOTICE - "INSERT INTO history (destination_id, local_path, operation, duration, date_finished_utc, date_modified_utc, size, message, plan_id, session_id, attempts, result, thumbnail_archive) VALUES(?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) ". Count: 488275. Total time: 64.25
2024-05-21 11:00:03,017 [SERV] [1] NOTICE - “DELETE FROM cloud_file_versions WHERE file_id IN (SELECT id FROM cloud_files WHERE destination_id = ?)”. Count: 1. Total time: 37.6
2024-05-21 11:00:03,085 [SERV] [1] NOTICE - "DELETE FROM differential_parts WHERE version_id IN (SELECT id FROM cloud_file_versions WHERE file_id IN (SELECT id FROM cloud_files WHERE destination_id = ?)) ". Count: 1. Total time: 5.79
2024-05-21 11:00:03,113 [SERV] [1] NOTICE - Total duration of queries: 328.09
2024-05-21 11:00:03,124 [SERV] [1] NOTICE - Request GET: success 1, failed 0
2024-05-21 11:00:03,131 [SERV] [1] NOTICE - Request LIST: success 494, failed 0
2024-05-21 11:00:03,155 [SERV] [1] NOTICE - Plan finished. MSP360 Backup Desktop Edition (formerly CloudBerry). Version: 7.9.4.103

I’ve run consistency checks in the past without issue and am unable to figure out what has changed. Based on this behavior, I do not plan on using this feature again.

I will rollback to restore the most recent backup prior to the most recent consistency check and assume all is well, since the local db has been sync’d with S3.

Can someone explain exactly how the consistency check works, or is supposed to work?

Can someone explain why the consistency check is clearing data from the local database?

Thanks in advance for any assistance with this issue.

AlexanderMSP360 · May 22, 2024, 10:01am

[reply=“Britt Burnett;d9749”] Consistency check just verifies that data on storage is consistent with the selected for backup source data.

I assume you are using legacy backup format, which is a low maintenance mode. Have you considered New Backup Format instead?

Britt_Burnett · May 22, 2024, 1:18pm

Hi Alexander. I appreciate the response but I don’t think you understand my issue. Did you read through the details? I am using legacy backup jobs.

I’ve been using Cloudberry Backup since 2017 and have had no issues with consistency checks that I’m aware of. Beginning recently, consistency check will delete all entries in the cbbackup database and data stored in the S3 repository is unaffected. The next time a backup runs, duplicate files are uloaded to the S3 repository, I assume because Cloudberry Backup has no knowledge of files being stored in the S3 repository since there is no data in the cbbackup database for the destination.

I’m able to reproduce this issue on demand:

Navigate to Backup Storage for the repository. Browse and restore various files to the local file system, confirm the restored files files are valid.
Run a Consistency Check for the repository. Wait for the Consistency Check to complete
Navigate to Backup Storage for the repository. The repository shows as empty. No files or folders are displayed for browsing.
S3 storage is unaffected.

The consistency check is doing more than simply comparing the local repository toe S3 storage and reporting differences:

Log files show these entries as part of the Consistency Check. All entries are deleted for the destination. 1001 is the destination id for the S3 repository affected.

ArchiveLiteSyncHelper.ExecuteCompleteConsistencyCheck: Start executing total consistency check…
2024-05-21 09:57:30,026 [PL] [5] NOTICE - ArchiveLiteSyncHelper.CommitSync: Committing sync changes complete…
2024-05-21 09:59:13,694 [PL] [13] NOTICE - SQL query ‘DELETE FROM cloud_file_versions WHERE file_id IN (SELECT id FROM cloud_files WHERE destination_id = ?)’. Parameters: ‘[param_1]=‘1001’’ takes in total: 00:01:03
2024-05-21 10:01:07,123 [PL] [13] NOTICE - SQL query ‘DELETE FROM cloud_files WHERE destination_id = ?’. Parameters: ‘[param_1]=‘1001’’ takes in total: 00:01:53
2024-05-21 10:01:12,681 [PL] [13] NOTICE - Sync for ‘AmazonS3-Dell5810-Standard-IA-US-East-Ohio’ is completed. Files: 492046, size: 1.66 TB, duration: 01:22:11

I’ve searched through forums and the knowledge base and am unable to find details of these warnings to know what this actually means. Can you help me understand the detail of these errors and what this means with regard to local files and files in the S3 destination, and what actions I may need to take on my part?

2024-05-21 09:57:28,211 [PL] [5] WARN - all: Cannot convert string ‘CBB_Archive\dell5810-standard-ia\ECBB_DELL5810\zzzz27ppn4tencbgnnk5jr4jvejxibleqo4ohwvspinneuuwvyaml6jops5hxkuq73sfxzhj65ipyuf2xna4zf64c66qmatma7fz74z4ghzclacv5ixvzgrwe3pnkbazob52v4g5vfar36pe23fszf46ojamif7y3xwbrznoni2mbpotywha====’ to storage path

2024-05-21 10:51:09,632 [PL] [1] WARN - File ECBB_DELL5810/xsmrclcce6st5pj2lhc6t74nyt2skrhpipqhoqnx533ijgvurus3t2xzbvkfcfjdx32eehzrz54pf24em4cp3wc2haxzodhz44oint5zmqkhxlejb2ht7lxk2zhhkhgmw3aj2sk63swnei3p5kxxi64cctgo5oxp3ebhszo7rkssvosjqz7dky7xmunldti4st5wnkblxkrjy=== will be ignored. History path:

AlexanderMSP360 · May 23, 2024, 8:30am

[reply=“Britt Burnett;11105”] This is most likely a software regression after one of the recent updates. This might be fixed with the next release. If you send me your contact email address in DM I can give you a pre-release build to test.