Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Backup with blobxfer Azure enabled doesn't cleanup old backups #333

Open
RPYoshi opened this issue Mar 25, 2024 · 0 comments
Open

Backup with blobxfer Azure enabled doesn't cleanup old backups #333

RPYoshi opened this issue Mar 25, 2024 · 0 comments
Labels
bug

Comments

@RPYoshi
Copy link

RPYoshi commented Mar 25, 2024

Summary

None of my backups older than the given DEFAULT_CLEANUP_TIME are getting removed.
It looks like at some point all backups are being touched which makes their modified timestamp to become the same time as the current backup process.
This makes the find command unable to successfully process older backups.

find "${backup_job_filesystem_path}"/ -type f -mmin +"${backup_job_cleanup_time}" -iname "${backup_job_filename_base}*" -exec rm -f {} \;

Screenshot below

I'm not sure when the files are being touched, but I think it might be during the blobxfer sync process.

Steps to reproduce

Environment variables I have set
DEFAULT_BACKUP_LOCATION = blobxfer
DEFAULT_BACKUP_INTERVAL = 2880
DEFAULT_CLEANUP_TIME = 10080

What is the expected correct behavior?

Expect backups to be removed older than the DEFAULT_CLEANUP_TIME using the find ... -exec rm-f command.

Relevant logs and/or screenshots

image

2024-03-23.03:00:06 [INFO] ** [03-MariaDB__nextcloud] Backup 03 routines finish time: 2024-03-23 03:00:06 PDT with exit code 0
2024-03-23.03:00:06 [NOTICE] ** [03-MariaDB__nextcloud] Backup 03 routines time taken: Hours: 0 Minutes: 00 Seconds: 06
2024-03-23.03:00:06 [NOTICE] ** [03-MariaDB__nextcloud] Sleeping for another 172794 seconds. Waking up at 2024-03-25 03:00:00 PDT 
2024-03-23.03:00:07 [NOTICE] ** [01-ImmichSQL__immich] Dumping PostgresSQL database: 'immich' and compressing with 'gzip'
2024-03-23.03:00:10 [INFO] ** [01-ImmichSQL__immich] DB Backup of 'pgsql_immich_immichsql_20240323-030007.sql.gz' completed successfully
2024-03-23.03:00:10 [NOTICE] ** [01-ImmichSQL__immich] Generating MD5 sum for 'pgsql_immich_immichsql_20240323-030007.sql.gz'
2024-03-23.03:00:10 [NOTICE] ** [01-ImmichSQL__immich] Backup of 'pgsql_immich_immichsql_20240323-030007.sql.gz' created with the size of 16661970 bytes
2024-03-23.03:00:10 [INFO] ** [01-ImmichSQL__immich] Synchronize local storage from S3 Bucket with blobxfer
2024-03-23 03:00:10.922 DEBUG - credential: account=******************* endpoint=core.windows.net is_sas=False can_create_containers=True can_list_container_objects=True can_read_object=True can_write_object=True
2024-03-23 03:00:10.926 INFO - 
============================================
         Azure blobxfer parameters
============================================
         blobxfer version: 1.11.0
                 platform: Linux-6.1.49-Unraid-x86_64-with
               components: CPython=3.11.6-64bit azstor.blob=2.1.0 azstor.file=2.1.0 crypt=41.0.7 req=2.31.0
       transfer direction: Azure -> local
                  workers: disk=9 xfer=6 (msoc=8) md5=0 crypto=0
                 log file: None
                  dry run: False
              resume file: None
                  timeout: connect=10 read=200 max_retries=1000
                     mode: StorageModes.File
                  skip on: fs_match=False lmt_ge=False md5=False
                   delete: extraneous=True only=False
                overwrite: True
                recursive: True
            rename single: False
         strip components: 0
         chunk size bytes: 0
         compute file md5: False
       restore properties: attr=False lmt=False
          rsa private key: None
        local destination: /backup/immich_sql
============================================
2024-03-23 03:00:10.927 INFO - blobxfer start time: 2024-03-23 03:00:10.926978-07:00
2024-03-23 03:00:10.927 DEBUG - dest is_dir=True for 1 specs
2024-03-23 03:00:10.927 INFO - downloading blobs/files to local path: /backup/immich_sql
2024-03-23 03:00:10.927 DEBUG - spawning 6 transfer threads
2024-03-23 03:00:10.944 DEBUG - spawning 9 disk threads
2024-03-23 03:00:11.431 DEBUG - 0 files 0.0000 MiB filesize, lmt_ge, or no overwrite skipped
2024-03-23 03:00:11.431 DEBUG - 14 remote files processed, waiting for download completion of approx. 111.2154 MiB
2024-03-23 03:00:11.629 INFO - MD5: SKIPPED, immich-sql/pgsql_immich_immichsql_20240314-121810.sql.gz None <L..R> None
2024-03-23 03:00:11.629 INFO - MD5: SKIPPED, immich-sql/pgsql_immich_immichsql_20240314-121810.sql.gz.md5 None <L..R> None
2024-03-23 03:00:11.630 INFO - MD5: SKIPPED, immich-sql/pgsql_immich_immichsql_20240314-122024.sql.gz.md5 None <L..R> None
2024-03-23 03:00:11.955 INFO - MD5: SKIPPED, immich-sql/pgsql_immich_immichsql_20240314-123255.sql.gz.md5 None <L..R> None
2024-03-23 03:00:12.104 INFO - MD5: SKIPPED, immich-sql/pgsql_immich_immichsql_20240315-030000.sql.gz.md5 None <L..R> None
2024-03-23 03:00:12.228 INFO - MD5: SKIPPED, immich-sql/pgsql_immich_immichsql_20240317-030000.sql.gz.md5 None <L..R> None
2024-03-23 03:00:12.229 INFO - MD5: SKIPPED, immich-sql/pgsql_immich_immichsql_20240314-123255.sql.gz None <L..R> None
2024-03-23 03:00:12.245 INFO - MD5: SKIPPED, immich-sql/pgsql_immich_immichsql_20240319-030000.sql.gz.md5 None <L..R> None
2024-03-23 03:00:12.301 INFO - MD5: SKIPPED, immich-sql/pgsql_immich_immichsql_20240321-030006.sql.gz.md5 None <L..R> None
2024-03-23 03:00:12.315 INFO - MD5: SKIPPED, immich-sql/pgsql_immich_immichsql_20240314-122024.sql.gz None <L..R> None
2024-03-23 03:00:12.486 INFO - MD5: SKIPPED, immich-sql/pgsql_immich_immichsql_20240315-030000.sql.gz None <L..R> None
2024-03-23 03:00:12.517 INFO - MD5: SKIPPED, immich-sql/pgsql_immich_immichsql_20240319-030000.sql.gz None <L..R> None
2024-03-23 03:00:12.529 INFO - MD5: SKIPPED, immich-sql/pgsql_immich_immichsql_20240317-030000.sql.gz None <L..R> None
2024-03-23 03:00:12.883 INFO - MD5: SKIPPED, immich-sql/pgsql_immich_immichsql_20240321-030006.sql.gz None <L..R> None
2024-03-23 03:00:12.890 INFO - attempting to delete 0 extraneous files
2024-03-23 03:00:12.890 INFO - elapsed download + verify time and throughput of 0.1086 GiB: 1.753 sec, 507.5932 Mbps (63.449 MiB/sec)
2024-03-23 03:00:12.890 INFO - blobxfer end time: 2024-03-23 03:00:12.890605-07:00 (elapsed: 1.964 sec)
2024-03-23.03:00:12 [INFO] ** [01-ImmichSQL__immich] Moving backup to external storage with blobxfer
2024-03-23.03:00:16 [NOTICE] ** [01-ImmichSQL__immich] DB Backup for 'immich' time taken: Hours: 0 Minutes: 00 Seconds: 09
+ '[' -n 10080 ']'
+ '[' '' '!=' 1 ']'
+ case "${backup_job_backup_location,,}" in
+ write_log info 'Cleaning up old backups on filesystem'
+ var_true ''
+ '[' '' = true ']'
+ '[' '' = yes ']'
+ output_off
+ '[' false = true ']'
+ local _arg_log_level=info
+ shift 1
+ local '_arg_log_message=Cleaning up old backups on filesystem'
+ '[' -n pgsql ']'
+ '[' -n immich ']'
+ '[' -n ImmichSQL ']'
+ '[' -n pgsql_immich_immichsql ']'
+ case "${_arg_log_level,,}" in
++ date '+%Y-%m-%d %H:%M:%S %Z'
++ date +%Y%m%d
+ echo '2024-03-23 03:00:16 PDT [info] Cleaning up old backups on filesystem'
++ date -d @1711188001 +%Y%m%d_%H%M%S
+ run_as_user tee -a /logs/20240323/20240323_030001-pgsql_immich_immichsql.log
+ sudo -Eu dbbackup tee -a /logs/20240323/20240323_030001-pgsql_immich_immichsql.log
+ print_info 'Cleaning up old backups on filesystem'
+ output_off
+ '[' false = true ']'
+ '[' false = true ']'
+ '[' '' = false ']'
++ log_prefix
++ output_off
++ '[' false = true ']'
++ '[' true = true ']'
+++ date +%Y-%m-%d
+++ date +%H:%M:%S
++ echo '2024-03-23.03:00:16 '
++ output_on
++ '[' false = true ']'
+ echo -e '2024-03-23.03:00:16 \e[42m[INFO]\e[49m ** [01-ImmichSQL__immich] Cleaning up old backups on filesystem'
2024-03-23.03:00:16 [INFO] ** [01-ImmichSQL__immich] Cleaning up old backups on filesystem
++ log_prefix
++ output_off
++ '[' false = true ']'
++ '[' true = true ']'
+++ date +%Y-%m-%d
+++ date +%H:%M:%S
++ echo '2024-03-23.03:00:16 '
++ output_on
++ '[' false = true ']'
++ basename ./run
+ echo -e '2024-03-23.03:00:16 [INFO] /etc/services.available/dbbackup-01/run ** [01-ImmichSQL__immich] Cleaning up old backups on filesystem'
+ output_on
+ '[' false = true ']'
+ output_on
+ '[' false = true ']'
+ var_true ''
+ '[' '' = true ']'
+ '[' '' = yes ']'
+ run_as_user mkdir -p /backup/immich_sql
+ sudo -Eu dbbackup mkdir -p /backup/immich_sql
+ find /backup/immich_sql/ -type f -mmin +10080 -iname 'pgsql_immich_immichsql*' -exec rm -f '{}' ';'
+ '[' -z ******************* ']'
+ '[' -z **************************************************************************************** ']'
+ write_log info 'Syncing changes via blobxfer'
+ var_true ''
+ '[' '' = true ']'
+ '[' '' = yes ']'
+ output_off
+ '[' false = true ']'
+ local _arg_log_level=info
+ shift 1
+ local '_arg_log_message=Syncing changes via blobxfer'
+ '[' -n pgsql ']'
+ '[' -n immich ']'
+ '[' -n ImmichSQL ']'
+ '[' -n pgsql_immich_immichsql ']'
+ case "${_arg_log_level,,}" in
++ date '+%Y-%m-%d %H:%M:%S %Z'
++ date +%Y%m%d
+ echo '2024-03-23 03:00:16 PDT [info] Syncing changes via blobxfer'
++ date -d @1711188001 +%Y%m%d_%H%M%S
+ run_as_user tee -a /logs/20240323/20240323_030001-pgsql_immich_immichsql.log
+ sudo -Eu dbbackup tee -a /logs/20240323/20240323_030001-pgsql_immich_immichsql.log
+ print_info 'Syncing changes via blobxfer'
+ output_off
+ '[' false = true ']'
+ '[' false = true ']'
+ '[' '' = false ']'
++ log_prefix
++ output_off
++ '[' false = true ']'
++ '[' true = true ']'
+++ date +%Y-%m-%d
+++ date +%H:%M:%S
++ echo '2024-03-23.03:00:16 '
++ output_on
++ '[' false = true ']'
+ echo -e '2024-03-23.03:00:16 \e[42m[INFO]\e[49m ** [01-ImmichSQL__immich] Syncing changes via blobxfer'
2024-03-23.03:00:16 [INFO] ** [01-ImmichSQL__immich] Syncing changes via blobxfer
++ '[' true = true ']'
+++ date +%Y-%m-%d
+++ date +%H:%M:%S
++ echo '2024-03-23.03:00:17 '
++ output_on
++ '[' false = true ']'
++ basename ./run
+ echo -e '2024-03-23.03:00:17 [INFO] /etc/services.available/dbbackup-01/run ** [01-ImmichSQL__immich] Syncing changes via blobxfer'
+ output_on
+ '[' false = true ']'
+ output_on
+ '[' false = true ']'
+ var_true ''
+ '[' '' = true ']'
+ '[' '' = yes ']'
+ silent run_as_user blobxfer upload --mode file --remote-path immich-sql --storage-account ******************* --storage-account-key **************************************************************************************** --local-path /backup/immich_sql --delete --delete-only
+ '[' FALSE = true ']'
+ '[' true = true ']'
+ run_as_user blobxfer upload --mode file --remote-path immich-sql --storage-account ******************* --storage-account-key **************************************************************************************** --local-path /backup/immich_sql --delete --delete-only
+ sudo -Eu dbbackup blobxfer upload --mode file --remote-path immich-sql --storage-account ******************* --storage-account-key **************************************************************************************** --local-path /backup/immich_sql --delete --delete-only
2024-03-23 03:00:17.188 DEBUG - credential: account=******************* endpoint=core.windows.net is_sas=False can_create_containers=True can_list_container_objects=True can_read_object=True can_write_object=True
2024-03-23 03:00:17.193 INFO - 
============================================
         Azure blobxfer parameters
============================================
         blobxfer version: 1.11.0
                 platform: Linux-6.1.49-Unraid-x86_64-with
               components: CPython=3.11.6-64bit azstor.blob=2.1.0 azstor.file=2.1.0 crypt=41.0.7 req=2.31.0
       transfer direction: local -> Azure
                  workers: disk=32 xfer=64 md5=0 crypto=0
                 log file: None
                  dry run: False
              resume file: None
                  timeout: connect=10 read=200 max_retries=1000
                     mode: StorageModes.File
                  skip on: fs_match=False lmt_ge=False md5=False
                   delete: extraneous=True only=True
                overwrite: True
                recursive: True
            rename single: False
         strip components: 0
              access tier: None
         chunk size bytes: 0
           one shot bytes: 0
         store properties: attr=False cc='' ct=<mime> md5=False
           rsa public key: None
       local source paths: /backup/immich_sql
============================================
2024-03-23 03:00:17.194 INFO - blobxfer start time: 2024-03-23 03:00:17.194072-07:00
2024-03-23 03:00:17.194 DEBUG - spawning 32 disk threads
2024-03-23 03:00:17.214 DEBUG - spawning 64 transfer threads
2024-03-23 03:00:17.237 INFO - skipping upload transfers as only deletion option was specified
2024-03-23 03:00:17.238 DEBUG - attempting to delete extraneous blobs/files from: *******************;core.windows.net;immich-sql
2024-03-23 03:00:17.351 INFO - deleted 0 extraneous blobs/files
2024-03-23 03:00:17.351 INFO - blobxfer end time: 2024-03-23 03:00:17.351758-07:00 (elapsed: 0.158 sec)

Environment

  • Image version / tag: latest (tiredofit/db-backup:latest)
  • Host OS: Unraid

Possible fixes

Instead of using the find command, actually parsing the filename would fix the problem. However I know that can be CPU heavy for some scenarios.
@RPYoshi RPYoshi added the bug label Mar 25, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@RPYoshi