Repeated backup failures with an app

[SansGuidon]

Hello,
I'm facing a lot of stability issues with a specific app and its backups, and I'm not sure if it's a general issue or app-specific one, hence the request for support here instead of in the very app specific forum section. Anyway feel free to move this topic elsewhere if it's too specific.

So the last backup is from 1 week ago (Sept 19) for some app (changedetection).
Since then, all dedicated backups tasks for this very app are stuck, the status in Cloudron app page is stuck at Backing up - Removing 1000 files from ***REDACTED***/snapshot/app_7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d/+-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/MsI8IMR7IMRPS7aT5qvcrpnlBR5Kr7AXggLB1fSpWiLhLhDz6ZAaO7JlAWcyusUYdHs8pfzWlS+IJCDgs-OW5Q/htrH97oS6J-iUgci3AdbFaVs3ZyELXy66BI2YXJ1U06wow5BL8fIEf5jpq2J54n8aKl5nV2e3srnAn-RTE6PQw to ***REDACTED***/snapshot/app_7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d/+-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/rBCzp6YXZGsVK1NCh2FcIgOxZaOt-dzi7yEkQuNJHSHbkjmDbFE7VImvgqRrejeQA7rRolHTSpnqpWLfo+TQaQ/EZEn5RmKuVdu2sZycxslrr3S6pDwqOuMzUXdPvywo5j23h5aSQBC170tpPgNk8FgeQsGuixv+EfX4vxWczC90A (changedetection.***REDACTED***)

The app logs :

Sep 23 19:35:41 box:syncer sync: processing 1 deletes and 2620 additions
Sep 23 19:35:41 box:backupformat/rsync sync: processing task: {"operation":"removedir","path":"","reason":"crash"}
Sep 23 19:35:41 box:backupformat/rsync Removing directory ***REDACTED***/snapshot/app_7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d
Sep 23 19:35:41 box:tasks update 2597: {"percent":30,"message":"Removing 1000 files from ***REDACTED***/snapshot/app_7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d/+-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/MsI8IMR7IMRPS7aT5qvcrpnlBR5Kr7AXggLB1fSpWiLhLhDz6ZAaO7JlAWcyusUYdHs8pfzWlS+IJCDgs-OW5Q/htrH97oS6J-iUgci3AdbFaVs3ZyELXy66BI2YXJ1U06wow5BL8fIEf5jpq2J54n8aKl5nV2e3srnAn-RTE6PQw to ***REDACTED***/snapshot/app_7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d/+-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/qYg8hLFfuEaGNVX3ZKX3DrVkG8mWDN83C-NzACUML6cRrmWBooz0zE7zgEnO1Hd--I-j+ZMcp5rJVQbUJkM+fw/4regPhKR4Ihxc7GYD172dZnDwukxgrjNRTXlJaYk2rke6rXoi5DwzSl5AUQsSSowSNPF4gduz4kqjGJnUl8R9w (***REDACTED***)"}
Sep 25 09:13:28 box:taskworker Starting task 2610. Logs are at /home/yellowtent/platformdata/logs/7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d/apptask.log
Sep 25 09:13:28 box:apptask run: startTask installationState: pending_configure runState: running
Sep 25 09:13:28 box:tasks update 2610: {"percent":10,"message":"Deleting old containers"}
Sep 25 09:13:28 box:shell reload /usr/bin/sudo -S /home/yellowtent/box/src/scripts/restartservice.sh nginx
Sep 25 09:13:28 box:apptask deleteContainer: deleting app containers (app, scheduler)
Sep 25 09:13:28 box:shell removeLogrotateConfig /usr/bin/sudo -S /home/yellowtent/box/src/scripts/configurelogrotate.sh remove 7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d
Sep 25 09:13:28 box:tasks update 2610: {"percent":20,"message":"Downloading icon"}
Sep 25 09:13:28 box:apptask downloadIcon: Downloading icon of io.changedetection.cloudronapp@1.11.4
Sep 25 09:13:29 box:tasks update 2610: {"percent":40,"message":"Downloading image"}
Sep 25 09:13:29 box:shell file execArgs: df ["-B1","--output=source,fstype,size,used,avail,pcent,target","/var/lib/docker"]
Sep 25 09:13:29 box:docker downloadImage cloudron/io.changedetection.cloudronapp:20240904-130305-8085b47c8
Sep 25 09:13:29 box:tasks update 2610: {"percent":45,"message":"Ensuring app data directory"}
Sep 25 09:13:29 box:tasks update 2610: {"percent":50,"message":"Setting up addons"}
Sep 25 09:13:29 box:services setupAddons: Setting up ["localstorage"]
Sep 25 09:13:29 box:services setupAddons: setting up addon localstorage with options {}
Sep 25 09:13:29 box:services setupLocalStorage
Sep 25 09:13:29 box:shell createVolume /usr/bin/sudo -S /home/yellowtent/box/src/scripts/mkdirvolume.sh /home/yellowtent/appsdata/7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d/data
Sep 25 09:13:29 box:tasks update 2610: {"percent":60,"message":"Creating container"}
Sep 25 09:13:29 box:apptask createContainer: creating container
Sep 25 09:13:31 box:shell addLogrotateConfig /usr/bin/sudo -S /home/yellowtent/box/src/scripts/configurelogrotate.sh add 7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d /tmp/7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d.logrotate
Sep 25 09:13:31 box:apptask startApp: starting container
Sep 25 09:13:31 box:tasks update 2610: {"percent":90,"message":"Configuring reverse proxy"}
Sep 25 09:13:31 box:shell providerMatches execArgs: openssl ["x509","-noout","-subject","-issuer"]
Sep 25 09:13:31 box:reverseproxy providerMatches: subject=CN = ***REDACTED*** domain=***REDACTED*** issuer=C = US, O = Let's Encrypt, CN = E5 wildcard=false/false prod=true/true issuerMismatch=false wildcardMismatch=false match=true
Sep 25 09:13:31 box:shell getCertificateDates execArgs: openssl ["x509","-startdate","-enddate","-subject","-noout"]
Sep 25 09:13:31 box:reverseproxy ensureCertificate: ***REDACTED*** acme cert exists and is up to date
Sep 25 09:13:31 box:reverseproxy expiryDate: subject=CN = ***REDACTED*** notBefore=Aug 8 05:12:02 2024 GMT notAfter=Nov 6 05:12:01 2024 GMT daysLeft=41.91561716435185
Sep 25 09:13:31 box:reverseproxy needsRenewal: false. force: false
Sep 25 09:13:31 box:shell isOscpEnabled execArgs: openssl ["x509","-in","/home/yellowtent/platformdata/nginx/cert/***REDACTED***.cert","-noout","-ocsp_uri"]
Sep 25 09:13:31 box:reverseproxy writeAppLocationNginxConfig: writing config for "***REDACTED***" to /home/yellowtent/platformdata/nginx/applications/7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d/***REDACTED***.conf with options {"sourceDir":"/home/yellowtent/box","vhost":"***REDACTED***","hasIPv6":true,"ip":"172.18.18.205","port":5000,"endpoint":"app","redirectTo":null,"certFilePath":"/home/yellowtent/platformdata/nginx/cert/***REDACTED***.cert","keyFilePath":"/home/yellowtent/platformdata/nginx/cert/***REDACTED***.key","robotsTxtQuoted":null,"cspQuoted":null,"hideHeaders":[],"proxyAuth":{"enabled":false,"id":"7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d","location":"/"},"upstreamUri":"","ocsp":true,"hstsPreload":false}
Sep 25 09:13:31 box:shell reload /usr/bin/sudo -S /home/yellowtent/box/src/scripts/restartservice.sh nginx
Sep 25 09:13:31 box:tasks update 2610: {"percent":100,"message":"Done"}
Sep 25 09:13:31 box:tasks setCompleted - 2610: {"result":null,"error":null}
Sep 25 09:13:31 box:tasks update 2610: {"percent":100,"result":null,"error":null}
Sep 25 09:13:31 box:taskworker Task took 3.554 seconds
Sep 25 09:15:58 box:taskworker Starting task 2633. Logs are at /home/yellowtent/platformdata/logs/7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d/apptask.log
Sep 25 09:15:58 box:apptask run: startTask installationState: pending_backup runState: running
Sep 25 09:15:58 box:tasks update 2633: {"percent":10,"message":"Backing up"}
Sep 25 09:15:58 box:backuptask backupApp: backing up ***REDACTED*** with tag 2024-09-25-071558-705
Sep 25 09:15:58 box:tasks update 2633: {"percent":30,"message":"Snapshotting app ***REDACTED***"}
Sep 25 09:15:58 box:services backupAddons
Sep 25 09:15:58 box:services backupAddons: backing up ["localstorage"]
Sep 25 09:15:58 box:backuptask snapshotApp: ***REDACTED*** took 0.009 seconds
Sep 25 09:15:58 box:tasks update 2633: {"percent":30,"message":"Uploading app snapshot ***REDACTED***"}
Sep 25 09:15:58 box:shell backup-snapshot/app_7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d /usr/bin/sudo -S -E --close-from=4 /home/yellowtent/box/src/scripts/backupupload.js snapshot/app_7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d rsync {"localRoot":"/home/yellowtent/appsdata/7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d","layout":[]}
Sep 25 09:15:59 box:backupupload Backing up {"localRoot":"/home/yellowtent/appsdata/7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d","layout":[]} to snapshot/app_7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d
Sep 25 09:15:59 box:backuptask upload: path snapshot/app_7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d format rsync dataLayout {"localRoot":"/home/yellowtent/appsdata/7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d","layout":[]}
Sep 25 09:15:59 box:backuptask upload: mount point status is {"state":"active"}
Sep 25 09:15:59 box:backuptask checkPreconditions: getting disk usage of /home/yellowtent/appsdata/7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d
Sep 25 09:15:59 box:shell checkPreconditions execArgs: du ["-Dsb","--exclude=*.lock","--exclude=dovecot.list.index.log.*","/home/yellowtent/appsdata/7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d"]
Sep 25 09:15:59 box:backuptask checkPreconditions: total required=190917728 available=Infinity
Sep 25 09:15:59 box:shell saveFsMetadata execArgs: find ["/home/yellowtent/appsdata/7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d","-type","d","-empty"]
Sep 25 09:15:59 box:shell saveFsMetadata execArgs: find ["/home/yellowtent/appsdata/7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d","-type","f","-executable"]
Sep 25 09:15:59 box:shell safeFsMetadata execArgs: find ["/home/yellowtent/appsdata/7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d","-type","l"]
Sep 25 09:16:00 box:syncer sync: processing 1 deletes and 2668 additions
Sep 25 09:16:00 box:backupformat/rsync Removing directory ***REDACTED***/snapshot/app_7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d
Sep 25 09:16:00 box:backupformat/rsync sync: processing task: {"operation":"removedir","path":"","reason":"crash"}
Sep 25 09:16:02 box:tasks update 2633: {"percent":30,"message":"Removing 1000 files from ***REDACTED***/snapshot/app_7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d/+-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/MsI8IMR7IMRPS7aT5qvcrpnlBR5Kr7AXggLB1fSpWiLhLhDz6ZAaO7JlAWcyusUYdHs8pfzWlS+IJCDgs-OW5Q/htrH97oS6J-iUgci3AdbFaVs3ZyELXy66BI2YXJ1U06wow5BL8fIEf5jpq2J54n8aKl5nV2e3srnAn-RTE6PQw to ***REDACTED***/snapshot/app_7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d/+-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/rBCzp6YXZGsVK1NCh2FcIgOxZaOt-dzi7yEkQuNJHSHbkjmDbFE7VImvgqRrejeQA7rRolHTSpnqpWLfo+TQaQ/EZEn5RmKuVdu2sZycxslrr3S6pDwqOuMzUXdPvywo5j23h5aSQBC170tpPgNk8FgeQsGuixv+EfX4vxWczC90A (***REDACTED***)"}
Sep 25 09:16:17 2024-09-25 07:16:17.844 | INFO | __main__:stats_thread_func:320 - Connections: Active count 0 of max 10, Total processed: 0.
Sep 25 09:16:17 2024-09-25 07:16:17.845 | INFO | __main__:stats_thread_func:325 - Memory: Used 24.9% (Limit 90%) - Available 11191.7MB.
...
Sep 25 09:17:17 2024-09-25 07:17:17.896 | INFO | __main__:stats_thread_func:320 - Connections: Active count 0 of max 10, Total processed: 0.
Sep 25 09:17:17 2024-09-25 07:17:17.897 | INFO | __main__:stats_thread_func:325 - Memory: Used 24.8% (Limit 90%) - Available 11163.4MB.
Sep 25 09:17:26 2024-09-25 07:17:26.086 | DEBUG | changedetectionio.flask_app:ticker_thread_check_time_launch_checks:1875 - > Queued watch UUID ee0f357e-591a-4d49-bfb2-2cd8a922bcf3 last checked at 1727241446 queued at 1727248646.08 priority 1727248646 jitter -0.46s, 7200.08s since last checked
Sep 25 09:17:26 2024-09-25 07:17:26.693 | INFO | changedetectionio.update_worker:run:255 - Processing watch UUID ee0f357e-591a-4d49-bfb2-2cd8a922bcf3 Priority 1727248646 URL https://wttr.in/Anderlecht?m2&lang=fr&format=%C+%t%c%f
Sep 25 09:17:26 2024-09-25 07:17:26.893 | DEBUG | changedetectionio.update_worker:run:576 - Watch ee0f357e-591a-4d49-bfb2-2cd8a922bcf3 done in 0.20s
Sep 25 09:17:27 2024-09-25 07:17:27.898 | INFO | __main__:stats_thread_func:320 - Connections: Active count 0 of max 10, Total processed: 0.
Sep 25 09:17:27 2024-09-25 07:17:27.899 | INFO | __main__:stats_thread_func:325 - Memory: Used 24.8% (Limit 90%) - Available 11157.5MB.
...
Sep 25 09:24:48 2024-09-25 07:24:48.301 | INFO | __main__:stats_thread_func:320 - Connections: Active count 0 of max 10, Total processed: 0.
Sep 25 09:24:48 2024-09-25 07:24:48.302 | INFO | __main__:stats_thread_func:325 - Memory: Used 25.0% (Limit 90%) - Available 11024.5MB.

So at this point I'm not sure what is being wrong since all other application backups are succeeding (18 out of 19) and what is even more strange, the global backup pages indicates that recent backups are all running fine for 19 apps out of 19, with changedetection taken into account.

But we can observe that for some days, the global backups were failing

I'm using Contabo box storage as backup, with rsync.

Backup Details
Id:box_v8.0.4_2eb8547e
Label:
Remote Path:2024-09-24-230036-619/box_v8.0.4
Date:25 septembre 2024 09:09
Version:v8.0.4
Format:rsync

the last global backup log with a failure, is from Sept 23, 2024, here is the log

Sep 23 13:35:14 box:tasks update 2595: {"percent":46.45454545454546,"message":"Copying +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/1Ff2uDiq0FJBiCASx828-rX19mPZIlvvTv9KasnL+Mvpze7LPXu-Aa5KDMUAKrsv2IsmgXUH+SrWKbG2G8cmWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/c+jYf5xr76gq81FCK1fDUc4UaSVhb4WTTO6cglNK4GqIiyQ5p5WJWcMhPDFEHreldB-rSc7EC9fYqPXOsvILjjszUIM13ZuWGWH2wPpJLms"}
....
Sep 23 13:35:19 box:tasks update 2595: {"percent":46.45454545454546,"message":"Copying +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/yzdVWvLnGqInmgV0iowUzBvONIIXYy5sS6Y00BrktlA/fafVDHFEC340ZL84sxiaFRKMKXw+e14CPiOSN0z1XHc/hjprtoxKXNgOmdTlxxgOkStBpUEoqHPmpJem9G0675M"}
Sep 23 13:35:19 box:tasks update 2595: {"percent":46.45454545454546,"message":"Copying 9zpGQTS3UZche6GQ47tXzP7EaJyoUuGEs+fostTm5XI"}
Sep 23 13:35:19 box:tasks update 2595: {"percent":46.45454545454546,"message":"Copying YNoW6AzegoTKzJYHs7mb9rQsTMo8spRfLSOjQJy70Mk"}
Sep 23 13:35:19 box:tasks update 2595: {"percent":46.45454545454546,"message":"Copying fQ+nHrDglHMMUKO1bl2UGlC-rBFqid8BdQ7cnt3Jruo"}
Sep 23 13:35:19 box:tasks update 2595: {"percent":46.45454545454546,"message":"Copying qX62gAiu+qMWjZ5PzbJ2ULUUL335FloZ0tg9dFGlVDA"}
Sep 23 13:35:53 box:tasks update 2595: {"percent":46.45454545454546,"message":"Copied 119 files with error: null"}
Sep 23 13:35:53 box:backuptask copy: copied successfully to 2024-09-23-102858-983/app_***REDACTED***_v1.14.25. Took 40.568 seconds
Sep 23 13:35:53 box:backuptask fullBackup: app ***REDACTED*** backup finished. Took 43.455 seconds
Sep 23 13:35:53 box:tasks update 2595: {"percent":46.45454545454546,"message":"Backing up ***REDACTED*** (11/19)"}
Sep 23 13:35:53 box:tasks update 2595: {"percent":51.00000000000001,"message":"Snapshotting app ***REDACTED***"}
Sep 23 13:35:53 box:services backupAddons
Sep 23 13:35:53 box:services backupAddons: backing up ["localstorage"]
Sep 23 13:35:53 box:backuptask snapshotApp: ***REDACTED*** took 0.004 seconds
Sep 23 13:35:53 box:tasks update 2595: {"percent":51.00000000000001,"message":"Uploading app snapshot ***REDACTED***"}
Sep 23 13:35:53 box:shell backup-snapshot/app_7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d /usr/bin/sudo -S -E --close-from=4 /home/yellowtent/box/src/scripts/backupupload.js snapshot/app_7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d rsync {"localRoot":"/home/yellowtent/appsdata/7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d","layout":[]}
Sep 23 13:35:54 box:backupupload Backing up {"localRoot":"/home/yellowtent/appsdata/7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d","layout":[]} to snapshot/app_7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d
Sep 23 13:35:54 box:backuptask upload: path snapshot/app_7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d format rsync dataLayout {"localRoot":"/home/yellowtent/appsdata/7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d","layout":[]}
Sep 23 13:35:54 box:backuptask upload: mount point status is {"state":"active"}
Sep 23 13:35:54 box:backuptask checkPreconditions: getting disk usage of /home/yellowtent/appsdata/7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d
Sep 23 13:35:54 box:shell checkPreconditions execArgs: du ["-Dsb","--exclude=*.lock","--exclude=dovecot.list.index.log.*","/home/yellowtent/appsdata/7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d"]
Sep 23 13:35:54 box:backuptask checkPreconditions: total required=177430791 available=Infinity
Sep 23 13:35:54 box:shell saveFsMetadata execArgs: find ["/home/yellowtent/appsdata/7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d","-type","d","-empty"]
Sep 23 13:35:54 box:shell saveFsMetadata execArgs: find ["/home/yellowtent/appsdata/7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d","-type","f","-executable"]
Sep 23 13:35:54 box:shell safeFsMetadata execArgs: find ["/home/yellowtent/appsdata/7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d","-type","l"]
Sep 23 13:35:55 box:syncer sync: processing 1 deletes and 2609 additions
Sep 23 13:35:55 box:backupformat/rsync sync: processing task: {"operation":"removedir","path":"","reason":"crash"}
Sep 23 13:35:55 box:backupformat/rsync Removing directory ***REDACTED***/snapshot/app_7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d
Sep 23 13:35:55 box:tasks update 2595: {"percent":51.00000000000001,"message":"Removing 1000 files from ***REDACTED***/snapshot/app_7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d/+-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/MsI8IMR7IMRPS7aT5qvcrpnlBR5Kr7AXggLB1fSpWiLhLhDz6ZAaO7JlAWcyusUYdHs8pfzWlS+IJCDgs-OW5Q/htrH97oS6J-iUgci3AdbFaVs3ZyELXy66BI2YXJ1U06wow5BL8fIEf5jpq2J54n8aKl5nV2e3srnAn-RTE6PQw to ***REDACTED***/snapshot/app_7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d/+-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/nlJDfKdTrFn-Vx1W9Lrwlbp5+j++b+8dzgPo8B4cQKmbOg9S7T1HL8sEjCLJzer8V7QDYNQTHv3e5FINzNbNhA/sxlvwh-XcCwCh9vVfEinWuEPT6gODiTTry7AVlRIT2Q (***REDACTED***)"}

I'm really confused, and at this point I'm not confident to restore changedetection from a previous state.
I've at least been able to download a Changedetection backup zip file thanks to their Admin UI. But I'd like ideally to fix the whole situation at the root cause level or at least understand what is happening and troubleshoot it step by step.
The backup tasks are just stuck unless I cancel them which anyway is not making progress

Extra context :

• I'm running Cloudron v8.0.6 (automatically updated this morning).
• version of Changedetection:

App Info

App Title and Versionchangedetection.io 0.46.04
App ID7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d
Package Version io.changedetection.cloudronapp@1.11.4
Installed At 11/12/2023
Last Updated 04/09/2024

• Also Contabo had a big outage at the beginning of september at their Nuremberg DC, which was solved "quickly" (within 1-2 days) but a few days later I noticed a problem specific the availability of my Contabo Box storage a few days after, which they also have solved, so my backups were also blocked for 1 week from from Sept 10 to Sept 17.

Thanks for your help !

[nebulon]

I would expect changedetection not having huge amounts of data, and if other apps backup fine, this is indeed strange. Do you see anything obvious around the app related backup folders via SSH on the mounted storage?

Like are attributes and permissions ok for example for .../snapshot/app_7dc1c994-f6f8-4b3b-b3ed-0bb7097bb83d? Can you delete that folder via SSH (only delete stuff in .../snapshot/ !)

[SansGuidon]

Thanks for the feedback !
For now after purging the path to this specific app snapshot through rclone purge command (and, in the middle of my way, use Cloudron admin UI to cancel the stuck backup task), I could rerun a new backup from a clean state which worked 🥳.
I've attempted a second backup which also worked.
I'll wait til the next day to see if the automatic backup succeed.

[SansGuidon]

So far the problem seems gone. Backups take quite some time and make me thing the process is sometimes stuck but that's likely related to the storage speed, I guess.
Anyway I consider the situation resolved, for now.

[nebulon]

Glad it works now, possibly something was off on that one folder then, preventing or stalling the delete operation from the backup task.

[SansGuidon]

Having a look at the global backup task log now it seems to take hours and seems stuck.

...
Sep 27 01:44:36 box:tasks update 2644: {"percent":46.45454545454546,"message":"Copying +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/1Ff2uDiq0FJBiCASx828-rX19mPZIlvvTv9KasnL+Mvpze7LPXu-Aa5KDMUAKrsv2IsmgXUH+SrWKbG2G8cmWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/el1yUFt9q+vF7wU+PUorQh+bug+RPb4XPDCqGBLTBwNqqV9oaNgs7sod7Zdv2SS04cAaBlBBAsdoO7YCQNPWoH9hAFMgN1t8IgsSXIGJA+E"}
Sep 27 01:44:36 box:tasks update 2644: {"percent":46.45454545454546,"message":"Copying +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/1Ff2uDiq0FJBiCASx828-rX19mPZIlvvTv9KasnL+Mvpze7LPXu-Aa5KDMUAKrsv2IsmgXUH+SrWKbG2G8cmWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/gR0FKpwmXOTt448s20n9Vdx9u6+X6MkYRsXhspsAlpBk3FiDd2J-KAzccYVT7KBvHDPpJte97we20tfT+68tnMgiqocFrVAFafDmK9IZht0"}
Sep 27 01:44:38 box:tasks update 2644: {"percent":46.45454545454546,"message":"Copying +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/1Ff2uDiq0FJBiCASx828-rX19mPZIlvvTv9KasnL+Mvpze7LPXu-Aa5KDMUAKrsv2IsmgXUH+SrWKbG2G8cmWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/h6ktzTFHvXAhKQZ+Rpo3kADFcNS8datgzudLKX-sLCRuE1tVqUy32talVF9iDgdncfA6pTlC775D2O2A9BNobAnOKSTDdwoMbAxzbygYVSQ"}
Sep 27 01:44:40 box:tasks update 2644: {"percent":46.45454545454546,"message":"Copying +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/1Ff2uDiq0FJBiCASx828-rX19mPZIlvvTv9KasnL+Mvpze7LPXu-Aa5KDMUAKrsv2IsmgXUH+SrWKbG2G8cmWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/hPzcGoNkm2GxUeaTMkz1IiWPuEmsRThMX8c3UfmPrm290IRjwX0rtpRlwdaQSehxB0lcf6iITQjgiq1vkgpmmwyhSoQ17IlyhsM5-1qo6gk"}
...
Sep 27 01:44:52 box:tasks update 2644: {"percent":46.45454545454546,"message":"Copying +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/1Ff2uDiq0FJBiCASx828-rX19mPZIlvvTv9KasnL+Mvpze7LPXu-Aa5KDMUAKrsv2IsmgXUH+SrWKbG2G8cmWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/wgORAkMQVHW4qqcDF08dDJNd5-2MLWPgoCHrqp-QyQy-++08LktkkrBcwMqEuOy4BCrwNKcWGqcD+fiHjdE7RRyNT-i6HpJaVTPoG-O4F04"}
Sep 27 01:44:52 box:tasks update 2644: {"percent":46.45454545454546,"message":"Copying +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/1Ff2uDiq0FJBiCASx828-rX19mPZIlvvTv9KasnL+Mvpze7LPXu-Aa5KDMUAKrsv2IsmgXUH+SrWKbG2G8cmWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/wizHcd-CKCvyUKH4svkmfrplXa-60Z-HA5NkCt71xKlSup+UWMWYLH37Ns086sRdmbPj+YMICTzZ5O6jAK9xn1CG1HuClQe9uHaY5kEY-YU"}
Sep 27 01:44:52 box:tasks update 2644: {"percent":46.45454545454546,"message":"Copying +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/1Ff2uDiq0FJBiCASx828-rX19mPZIlvvTv9KasnL+Mvpze7LPXu-Aa5KDMUAKrsv2IsmgXUH+SrWKbG2G8cmWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/yMYYgXsnQ8fAlolxbAQa0iTygfSYXFFIap2ANUDZFyjwOqxo8SKkBRVDUXMkGXy9FtFgltKqACBLEpry90N8PaItwL4hGcEXIMVvDOUSLh4"}
Sep 27 01:44:52 box:tasks update 2644: {"percent":46.45454545454546,"message":"Copying +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/1Ff2uDiq0FJBiCASx828-rX19mPZIlvvTv9KasnL+Mvpze7LPXu-Aa5KDMUAKrsv2IsmgXUH+SrWKbG2G8cmWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/zad6Ziin-IUOOGGk-bgP4Awxl59Xz4lsVVLBG7u7JVRSzMRktpSo+ecRzP-qlIThIVUgs8sNg6JNgDUfyFYiSw-NZPgKi4z+Gw4Uhp56mfc"}
Sep 27 01:44:52 box:tasks update 2644: {"percent":46.45454545454546,"message":"Copying +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/1Ff2uDiq0FJBiCASx828-rX19mPZIlvvTv9KasnL+Mvpze7LPXu-Aa5KDMUAKrsv2IsmgXUH+SrWKbG2G8cmWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/zj5fRln7KTdIyTG6J1TCBWdxezzyVEJDSFoOqzTI94dnO6Riatt5CRcbYUNo53lh3FOy5AmtJBvpfg7Z+oKFv+SZ4L9qRaMyxoXDgIBo7KE"}
...
Sep 27 03:14:36 box:tasks update 2644: {"percent":46.45454545454546,"message":"Retrying (1) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/1Ff2uDiq0FJBiCASx828-rX19mPZIlvvTv9KasnL+Mvpze7LPXu-Aa5KDMUAKrsv2IsmgXUH+SrWKbG2G8cmWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/c+jYf5xr76gq81FCK1fDUc4UaSVhb4WTTO6cglNK4GqIiyQ5p5WJWcMhPDFEHreldB-rSc7EC9fYqPXOsvILjjszUIM13ZuWGWH2wPpJLms. Error: 504: null 504"}
...
Sep 27 04:45:17 box:tasks update 2644: {"percent":46.45454545454546,"message":"Retrying (2) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/U58FuxWQmXM04fxhZkwwPmOrt7d3+rOSLfCHv07RhU2zX-4cA2Wj-QxqshI1UxxaqIQ7Re4iFVBC+VBOcdleWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/YFtYX5hLWzIKz8PIqgtS216yGWBtdNs0+u9PEsKHYgyW9MQdpYxKvHFXWqGiElQnE3EiLZAl2DOVzWrHFGPBhEh9LQLkjK+J24WNb8qcEtI. Error: 504: null 504"}
Sep 27 06:15:15 box:tasks update 2644: {"percent":46.45454545454546,"message":"Retrying (3) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/1Ff2uDiq0FJBiCASx828-rX19mPZIlvvTv9KasnL+Mvpze7LPXu-Aa5KDMUAKrsv2IsmgXUH+SrWKbG2G8cmWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/c+jYf5xr76gq81FCK1fDUc4UaSVhb4WTTO6cglNK4GqIiyQ5p5WJWcMhPDFEHreldB-rSc7EC9fYqPXOsvILjjszUIM13ZuWGWH2wPpJLms. Error: 504: null 504"}
Sep 27 06:15:15 box:tasks update 2644: {"percent":46.45454545454546,"message":"Retrying (3) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/1Ff2uDiq0FJBiCASx828-rX19mPZIlvvTv9KasnL+Mvpze7LPXu-Aa5KDMUAKrsv2IsmgXUH+SrWKbG2G8cmWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/ed9-XRtQPFH6Pf9GgV8TPUZWfSTmtHIIxWvxApn-MgMGDN7hu64edxFVB7KVKXfbctH0mKpX3NjzOHT5Z+xQfawNBGLjZNQqrN0LmpY4AGU. Error: 504: null 504"}
Sep 27 06:15:34 box:tasks update 2644: {"percent":46.45454545454546,"message":"Retrying (3) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/U58FuxWQmXM04fxhZkwwPmOrt7d3+rOSLfCHv07RhU2zX-4cA2Wj-QxqshI1UxxaqIQ7Re4iFVBC+VBOcdleWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/KySiM+lFfMMIsqgY0F6zzeH46Aqt8xCkFCfzuN0odSLoxdyIcZTwiZcAi3FZ3hdrAA-OoG4LkTwcapOtohQCzvjssKpo4dmSeBRLY8rEJDM. Error: 504: null 504"}
Sep 27 06:15:36 box:tasks update 2644: {"percent":46.45454545454546,"message":"Retrying (3) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWTRVg8zyOQHxFtrW9PSg/U58FuxWQmXM04fxhZkwwPmOrt7d3+rOSLfCHv07RhU2zX-4cA2Wj-QxqshI1UxxaqIQ7Re4iFVBC+VBOcdleWg/GVjP4aiFVvSHFik-l75pxFHEU5NkaRki6FhmG+jhGMs/YFtYX5hLWzIKz8PIqgtS216yGWBtdNs0+u9PEsKHYgyW9MQdpYxKvHFXWqGiElQnE3EiLZAl2DOVzWrHFGPBhEh9LQLkjK+J24WNb8qcEtI. Error: 504: null 504"}

Not having my laptop with me to look further until Monday, only other thing I notice is the increasing huge size of backups on remote storage, like 90-100GB of backups for maybe a few hundred MBs worth of data for some apps.

Current status is Retrying (4) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/oHYKKHsp5nbpcywk51Jh-qadnitsJW2gf8LvyNVo0p4/JFrg5i70q68kJ2fb9TRxQhKuzyM8e7TIid8hUpVNUnTUO2OC0n9TVKwiecXpntDKgFWT

[SansGuidon]

So far it's progressing again, around 20% further, after 3 hours

Sep 27 09:34:54 box:tasks update 2644: {"percent":64.63636363636364,"message":"Copying +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/bCsBHeTNFOA0PMfeHwtd1DqpwCaS0XLjnW+4F8ZpP4g/OZ18TuP+eoUKZmW0j54+-6KQXwFof55visHM89cem4A/kMAZeKzls8+PKNLMRAfK8MAGYpb9DqXiZHcZPkdUaSA/5pa6SeARNoGyhcT1VO4sfWspp5yLCxPK5JkT6fEId9s/hLfwbzJOjjuoazhfyFRSV+OeZ78xlTbZId3UjUrO6aw"}
Sep 27 09:34:55 box:tasks update 2644: {"percent":64.63636363636364,"message":"Copying +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/bCsBHeTNFOA0PMfeHwtd1DqpwCaS0XLjnW+4F8ZpP4g/OZ18TuP+eoUKZmW0j54+-6KQXwFof55visHM89cem4A/kMAZeKzls8+PKNLMRAfK8MAGYpb9DqXiZHcZPkdUaSA/5pa6SeARNoGyhcT1VO4sfWspp5yLCxPK5JkT6fEId9s/hunSoQUKa6Z9QyvaoUtpCzgW5vTHNO6PTJhlSF1vqaQ"}
S
...

[SansGuidon]

@nebulon
I still have recurrent backup issues, it seems my daily backups take the whole night to run because of changedetection backup tasks which itself takes 7 hours

For now I've adapted the backup times and updates times to not overlap, as previously it was setup to update up to 4 times a day (11PM, 1AM, 3AM, 5AM) and backup around 1AM, so I was first worried that that backup and updates time were scheduled at the same hour.

$ rg -N -i "backup.*finished" task-2682.log 
2024-10-01T21:00:13.529Z box:backuptask fullBackup: app calibre.**MYDOMAIN** backup finished. Took 10.956 seconds
2024-10-01T21:07:59.625Z box:backuptask fullBackup: app syncthing.**MYDOMAIN** backup finished. Took 466.094 seconds
2024-10-01T21:32:59.350Z box:backuptask fullBackup: app n8n.**MYDOMAIN** backup finished. Took 1499.725 seconds
2024-10-01T21:33:42.927Z box:backuptask fullBackup: app music.**MYDOMAIN** backup finished. Took 43.576 seconds
2024-10-01T21:36:41.189Z box:backuptask fullBackup: app miniflux.**MYDOMAIN** backup finished. Took 178.262 seconds
2024-10-01T21:37:01.494Z box:backuptask fullBackup: app classic.**MYDOMAIN** backup finished. Took 20.305 seconds
2024-10-01T21:39:12.605Z box:backuptask fullBackup: app rssbridge.**MYDOMAIN** backup finished. Took 131.11 seconds
2024-10-01T23:01:11.683Z box:backuptask fullBackup: app nextcloud.**MYDOMAIN** backup finished. Took 4919.077 seconds
2024-10-01T23:01:36.977Z box:backuptask fullBackup: app todo.**MYDOMAIN** backup finished. Took 25.293 seconds
2024-10-01T23:05:57.089Z box:backuptask fullBackup: app invoice.**MYDOMAIN** backup finished. Took 260.111 seconds
2024-10-02T05:59:52.457Z box:backuptask fullBackup: app changedetection.**MYDOMAIN** backup finished. Took 24835.367 seconds
2024-10-02T05:59:54.625Z box:backuptask fullBackup: app collabora.**MYDOMAIN** backup finished. Took 2.168 seconds
2024-10-02T05:59:56.718Z box:backuptask fullBackup: app shaarli.**MYDOMAIN** backup finished. Took 2.093 seconds
2024-10-02T06:53:37.982Z box:backuptask fullBackup: app morgan.**MYDOMAIN** backup finished. Took 3221.263 seconds
2024-10-02T07:06:48.956Z box:backuptask fullBackup: app gitea.**MYDOMAIN** backup finished. Took 790.973 seconds
2024-10-02T07:28:25.837Z box:backuptask fullBackup: app wallabag.**MYDOMAIN** backup finished. Took 1296.88 seconds
2024-10-02T07:28:29.769Z box:backuptask fullBackup: app ntfy.**MYDOMAIN** backup finished. Took 3.931 seconds
2024-10-02T07:28:34.238Z box:backuptask fullBackup: app privatebin.**MYDOMAIN** backup finished. Took 4.469 seconds
2024-10-02T07:31:56.494Z box:backuptask fullBackup: app vault.**MYDOMAIN** backup finished. Took 202.254 seconds

and the lines in error

$ rg -N -i error task-2682.log 
2024-10-01T21:00:04.309Z box:syncer sync: done processing deletes. error: null
2024-10-01T21:00:04.735Z box:syncer sync: done processing adds. error: null
2024-10-01T21:00:04.736Z box:backupupload upload completed. error: null
2024-10-01T21:00:13.523Z box:tasks update 2682: {"percent":5.545454545454546,"message":"Copied 14 files with error: null"}
2024-10-01T21:00:56.018Z box:syncer sync: done processing deletes. error: null
2024-10-01T21:01:32.075Z box:syncer sync: done processing adds. error: null
2024-10-01T21:01:32.076Z box:backupupload upload completed. error: null
2024-10-01T21:07:59.618Z box:tasks update 2682: {"percent":10.090909090909092,"message":"Copied 366 files with error: null"}
2024-10-01T21:08:03.183Z box:syncer sync: done processing deletes. error: null
2024-10-01T21:08:11.832Z box:syncer sync: done processing adds. error: null
2024-10-01T21:08:11.834Z box:backupupload upload completed. error: null
2024-10-01T21:32:59.346Z box:tasks update 2682: {"percent":14.636363636363637,"message":"Copied 4354 files with error: null"}
2024-10-01T21:33:01.587Z box:syncer sync: done processing deletes. error: null
2024-10-01T21:33:05.030Z box:syncer sync: done processing adds. error: null
2024-10-01T21:33:05.031Z box:backupupload upload completed. error: null
2024-10-01T21:33:42.923Z box:tasks update 2682: {"percent":19.181818181818183,"message":"Copied 80 files with error: null"}
2024-10-01T21:33:52.627Z box:syncer sync: done processing deletes. error: null
2024-10-01T21:36:14.400Z box:syncer sync: done processing adds. error: null
2024-10-01T21:36:14.402Z box:backupupload upload completed. error: null
2024-10-01T21:36:41.185Z box:tasks update 2682: {"percent":23.72727272727273,"message":"Copied 4 files with error: null"}
2024-10-01T21:36:42.845Z box:syncer sync: done processing deletes. error: null
2024-10-01T21:36:44.070Z box:syncer sync: done processing adds. error: null
2024-10-01T21:36:44.071Z box:backupupload upload completed. error: null
2024-10-01T21:37:01.490Z box:tasks update 2682: {"percent":28.272727272727277,"message":"Copied 39 files with error: null"}
2024-10-01T21:37:22.150Z box:syncer sync: done processing deletes. error: null
2024-10-01T21:38:27.951Z box:syncer sync: done processing adds. error: null
2024-10-01T21:38:27.952Z box:backupupload upload completed. error: null
2024-10-01T21:39:12.599Z box:tasks update 2682: {"percent":32.81818181818182,"message":"Copied 134 files with error: null"}
2024-10-01T21:39:16.728Z box:syncer sync: done processing deletes. error: null
2024-10-01T21:39:24.566Z box:syncer sync: done processing adds. error: null
2024-10-01T21:39:24.568Z box:backupupload upload completed. error: null
2024-10-01T23:01:11.678Z box:tasks update 2682: {"percent":37.36363636363637,"message":"Copied 16600 files with error: null"}
2024-10-01T23:01:14.762Z box:syncer sync: done processing deletes. error: null
2024-10-01T23:01:25.356Z box:syncer sync: done processing adds. error: null
2024-10-01T23:01:25.356Z box:backupupload upload completed. error: null
2024-10-01T23:01:36.972Z box:tasks update 2682: {"percent":41.909090909090914,"message":"Copied 10 files with error: null"}
2024-10-01T23:01:43.858Z box:syncer sync: done processing deletes. error: null
2024-10-01T23:02:19.004Z box:syncer sync: done processing adds. error: null
2024-10-01T23:02:19.005Z box:backupupload upload completed. error: null
2024-10-01T23:05:57.079Z box:tasks update 2682: {"percent":46.45454545454546,"message":"Copied 121 files with error: null"}
2024-10-01T23:11:41.504Z box:syncer sync: done processing deletes. error: null
2024-10-01T23:11:56.470Z box:backupformat/rsync sync: processing task: {"operation":"add","path":"data/datastore/2f64cba3-c06f-458b-9bdc-b3cc2d5bae9e/last-error.txt","reason":"new","position":43}
2024-10-01T23:11:56.470Z box:backupformat/rsync Adding data/datastore/2f64cba3-c06f-458b-9bdc-b3cc2d5bae9e/last-error.txt position 43 try 1
2024-10-01T23:12:23.597Z box:backupformat/rsync sync: processing task: {"operation":"add","path":"data/datastore/e7b2faad-6ded-479b-9aeb-727a93a2c95c/last-error.txt","reason":"new","position":152}
2024-10-01T23:12:23.597Z box:backupformat/rsync Adding data/datastore/e7b2faad-6ded-479b-9aeb-727a93a2c95c/last-error.txt position 152 try 1
2024-10-01T23:12:24.974Z box:backupformat/rsync sync: processing task: {"operation":"add","path":"data/datastore/f8b18bd9-87a9-424d-947a-859ea75412f6/last-error-screenshot.png","reason":"changed","position":156}
2024-10-01T23:12:24.974Z box:backupformat/rsync Adding data/datastore/f8b18bd9-87a9-424d-947a-859ea75412f6/last-error-screenshot.png position 156 try 1
2024-10-01T23:13:00.011Z box:syncer sync: done processing adds. error: null
2024-10-01T23:13:00.012Z box:backupupload upload completed. error: null
2024-10-02T01:02:54.344Z box:tasks update 2682: {"percent":51.00000000000001,"message":"Retrying (1) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/zTG0KK7-TzPYcHM8n7gP17PHvPHXM42fyDh-cFvRGjPJqZjo5zia+0aptV88Q2hSZyeX3SQB2agrXL5Mk+7sZA/fVakjWVElvE8zFgXT--GiPO1sOkiN9EP08kdlVQs0ofVQ2XYKOKkvRM3znO8hI-K. Error: 504: null 504"}
2024-10-02T01:02:57.908Z box:tasks update 2682: {"percent":51.00000000000001,"message":"Retrying (1) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/zlBri0j-vBuhPEVuyBLawcIZUqIO-rvtJbXK-LY3gXGDAhJoqkU1Er5kSi7Iy3owLQE7nizkWMieGy4+38bdyg/+U2Q-AnDdQL5t-omn0NjxwR-Q2WC64DR70L3qWSkVqY. Error: 504: null 504"}
2024-10-02T02:33:14.073Z box:tasks update 2682: {"percent":51.00000000000001,"message":"Retrying (2) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/zTG0KK7-TzPYcHM8n7gP17PHvPHXM42fyDh-cFvRGjPJqZjo5zia+0aptV88Q2hSZyeX3SQB2agrXL5Mk+7sZA/fVakjWVElvE8zFgXT--GiPO1sOkiN9EP08kdlVQs0ofVQ2XYKOKkvRM3znO8hI-K. Error: 504: null 504"}
2024-10-02T02:33:17.536Z box:tasks update 2682: {"percent":51.00000000000001,"message":"Retrying (2) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/zlBri0j-vBuhPEVuyBLawcIZUqIO-rvtJbXK-LY3gXGDAhJoqkU1Er5kSi7Iy3owLQE7nizkWMieGy4+38bdyg/+U2Q-AnDdQL5t-omn0NjxwR-Q2WC64DR70L3qWSkVqY. Error: 504: null 504"}
2024-10-02T04:03:33.790Z box:tasks update 2682: {"percent":51.00000000000001,"message":"Retrying (3) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/zTG0KK7-TzPYcHM8n7gP17PHvPHXM42fyDh-cFvRGjPJqZjo5zia+0aptV88Q2hSZyeX3SQB2agrXL5Mk+7sZA/fVakjWVElvE8zFgXT--GiPO1sOkiN9EP08kdlVQs0ofVQ2XYKOKkvRM3znO8hI-K. Error: 504: null 504"}
2024-10-02T04:03:37.184Z box:tasks update 2682: {"percent":51.00000000000001,"message":"Retrying (3) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/zlBri0j-vBuhPEVuyBLawcIZUqIO-rvtJbXK-LY3gXGDAhJoqkU1Er5kSi7Iy3owLQE7nizkWMieGy4+38bdyg/+U2Q-AnDdQL5t-omn0NjxwR-Q2WC64DR70L3qWSkVqY. Error: 504: null 504"}
2024-10-02T05:33:53.685Z box:tasks update 2682: {"percent":51.00000000000001,"message":"Retrying (4) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/zTG0KK7-TzPYcHM8n7gP17PHvPHXM42fyDh-cFvRGjPJqZjo5zia+0aptV88Q2hSZyeX3SQB2agrXL5Mk+7sZA/fVakjWVElvE8zFgXT--GiPO1sOkiN9EP08kdlVQs0ofVQ2XYKOKkvRM3znO8hI-K. Error: 504: null 504"}
2024-10-02T05:33:56.993Z box:tasks update 2682: {"percent":51.00000000000001,"message":"Retrying (4) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/zlBri0j-vBuhPEVuyBLawcIZUqIO-rvtJbXK-LY3gXGDAhJoqkU1Er5kSi7Iy3owLQE7nizkWMieGy4+38bdyg/+U2Q-AnDdQL5t-omn0NjxwR-Q2WC64DR70L3qWSkVqY. Error: 504: null 504"}
2024-10-02T05:59:32.267Z box:tasks update 2682: {"percent":51.00000000000001,"message":"Retrying (5) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/zlBri0j-vBuhPEVuyBLawcIZUqIO-rvtJbXK-LY3gXGDAhJoqkU1Er5kSi7Iy3owLQE7nizkWMieGy4+38bdyg/+U2Q-AnDdQL5t-omn0NjxwR-Q2WC64DR70L3qWSkVqY. Error: XMLParserError: Non-whitespace before first tag.\nLine: 0\nColumn: 1\nChar: { 502"}
2024-10-02T05:59:32.274Z box:tasks update 2682: {"percent":51.00000000000001,"message":"Retrying (5) copy of +-SqAUe7wm42qtKljEa0rA5Org2aerAP0dRZ+xrfGA8/l5gkgMssQV3WZN4rGfLDET6XHh1q-3NvNH24UfTUuKI/zTG0KK7-TzPYcHM8n7gP17PHvPHXM42fyDh-cFvRGjPJqZjo5zia+0aptV88Q2hSZyeX3SQB2agrXL5Mk+7sZA/fVakjWVElvE8zFgXT--GiPO1sOkiN9EP08kdlVQs0ofVQ2XYKOKkvRM3znO8hI-K. Error: XMLParserError: Non-whitespace before first tag.\nLine: 0\nColumn: 1\nChar: { 502"}
2024-10-02T05:59:52.451Z box:tasks update 2682: {"percent":51.00000000000001,"message":"Copied 2607 files with error: null"}
2024-10-02T05:59:53.832Z box:syncer sync: done processing deletes. error: null
2024-10-02T05:59:54.326Z box:syncer sync: done processing adds. error: null
2024-10-02T05:59:54.330Z box:backupupload upload completed. error: null
2024-10-02T05:59:54.622Z box:tasks update 2682: {"percent":55.545454545454554,"message":"Copied 4 files with error: null"}
2024-10-02T05:59:55.789Z box:syncer sync: done processing deletes. error: null
2024-10-02T05:59:56.065Z box:syncer sync: done processing adds. error: null
2024-10-02T05:59:56.066Z box:backupupload upload completed. error: null
2024-10-02T05:59:56.715Z box:tasks update 2682: {"percent":60.0909090909091,"message":"Copied 22 files with error: null"}
2024-10-02T06:00:12.505Z box:syncer sync: done processing deletes. error: null
2024-10-02T06:02:39.143Z box:syncer sync: done processing adds. error: null
2024-10-02T06:02:39.145Z box:backupupload upload completed. error: null
2024-10-02T06:53:37.976Z box:tasks update 2682: {"percent":64.63636363636364,"message":"Copied 13894 files with error: null"}
2024-10-02T06:58:36.013Z box:syncer sync: done processing deletes. error: null
2024-10-02T07:02:37.378Z box:syncer sync: done processing adds. error: null
2024-10-02T07:02:37.380Z box:backupupload upload completed. error: null
2024-10-02T07:06:48.951Z box:tasks update 2682: {"percent":69.18181818181819,"message":"Copied 1553 files with error: null"}
2024-10-02T07:06:53.706Z box:syncer sync: done processing deletes. error: null
2024-10-02T07:06:56.646Z box:syncer sync: done processing adds. error: null
2024-10-02T07:06:56.648Z box:backupupload upload completed. error: null
2024-10-02T07:28:25.828Z box:tasks update 2682: {"percent":73.72727272727273,"message":"Copied 6783 files with error: null"}
2024-10-02T07:28:27.921Z box:syncer sync: done processing deletes. error: null
2024-10-02T07:28:29.538Z box:syncer sync: done processing adds. error: null
2024-10-02T07:28:29.539Z box:backupupload upload completed. error: null
2024-10-02T07:28:29.766Z box:tasks update 2682: {"percent":78.27272727272728,"message":"Copied 6 files with error: null"}
2024-10-02T07:28:31.040Z box:syncer sync: done processing deletes. error: null
2024-10-02T07:28:31.394Z box:syncer sync: done processing adds. error: null
2024-10-02T07:28:31.394Z box:backupupload upload completed. error: null
2024-10-02T07:28:34.235Z box:tasks update 2682: {"percent":82.81818181818183,"message":"Copied 16 files with error: null"}
2024-10-02T07:28:35.893Z box:syncer sync: done processing deletes. error: null
2024-10-02T07:28:38.026Z box:syncer sync: done processing adds. error: null
2024-10-02T07:28:38.027Z box:backupupload upload completed. error: null
2024-10-02T07:31:56.485Z box:tasks update 2682: {"percent":87.36363636363637,"message":"Copied 527 files with error: null"}
2024-10-02T07:31:57.821Z box:syncer sync: done processing deletes. error: null
2024-10-02T07:31:59.458Z box:syncer sync: done processing adds. error: null
2024-10-02T07:31:59.459Z box:backupupload upload completed. error: null
2024-10-02T07:32:00.274Z box:tasks update 2682: {"percent":91.90909090909092,"message":"Copied 7 files with error: null"}
2024-10-02T07:32:02.436Z box:syncer sync: done processing deletes. error: null
2024-10-02T07:32:04.590Z box:syncer sync: done processing adds. error: null
2024-10-02T07:32:04.590Z box:backupupload upload completed. error: null
2024-10-02T07:32:04.716Z box:tasks update 2682: {"percent":96.45454545454547,"message":"Copied 2 files with error: null"}
2024-10-02T07:32:04.719Z box:tasks setCompleted - 2682: {"result":"box_v8.0.6_5071cb76","error":null}
2024-10-02T07:32:04.720Z box:tasks update 2682: {"percent":100,"result":"box_v8.0.6_5071cb76","error":null}

Other details :

• The app is currently using 193.72 MB of storage (as of 05:15).
• There are hundred of watches configured in Changedetection.
• I didn't observe any outage or issue with resource usage during the backup.
  

I'm not sure how to improve this but I become a bit anxious about this. I can provide more details at need.

Thanks in advance !

[nebulon]

Not sure why that one app which doesn't even have that much data would take so incredibly long. If you trigger a backup for just that app, are the lots of retries in the task logs or other indicator why it would be so slow?

[SansGuidon]

When doing a backup for just that app it takes around 20 min to complete...
I don't get it

However I noticed the backup cleaner errored a lot in past days. That might explain also why my used storage only gets bigger for a few weeks, those retention logs rail daily without notification with those errors

box:database Connection 463 error: Packets out of order. Got: 0 Expected: 2 PROTOCOL_PACKETS_OUT_OF_ORDER

Related to https://forum.cloudron.io/topic/12200/backup-failed-packets-out-of-order?_=1727893829155 and more recent https://forum.cloudron.io/topic/12527/backup-fails-about-50-60-of-the-time ?

Not sure if related but I observe also very frequent network issues recently in miniflux with lot of feeds broken daily...

Miniflux is not able to reach this website due to a network error: Get "https://annas-archive.se/blog/rss.xml": dial tcp: lookup annas-archive.se on 127.0.0.11:53: server misbehaving
...
errors - Miniflux is not able to reach this website due to a network error: Get "https://www.green-coding.berlin/blog/index.xml": dial tcp [2a06:98c1:3121::3]:443: connect: network is unreachable
...

Etc.
I probably had to manually refresh 40-50 feeds today. And now I see that 150 feeds are in error. And fixing each takes a few retries with the Refresh.

and WordPress... (Broken link detector plugin seems more flakky and reports false positive)

Also this occured but only once and for first time today

Relay error: Connect to port25check.cloudron.io timed out. Check if port 25 (outbound) is blocked

So I'm keeping faith that somehow those issues and the other backup related issues open in support forum are related and ring a bell to someone.
I see other people have had either DNS or Backup issues recently in the support forum, so I feel not totally isolated. But also I think there are several issues that make it difficult for me to understand. Maybe I should try another VPS and storage...if that could be the problem. At this point every week seems to reveal more issues since the first of September.

BTW is it possible to reopen the thread/question ? it's not resolved in the end

[SansGuidon]

It seems I could reproduce a lot of the network errors / DNS resolution from the VPS's terminal/CLI, so I did some testing and my VPS provider's default DNS setup was the culprit and gave me lot of timeouts. See also https://www.thomasmartens.eu/contabo-dns-lookup-timeouts/ which helped me figure it out.

The solution for DNS so :

• replacing Contabo DNS servers and using instead 1.1.1.1 and 9.9.9.9 in /etc/netplan/01-netcfg.yaml
• run sudo netplan apply
• check resolvectl status

Refreshing all miniflux feeds, after a restart of its app, took only 1-2 secs
I'll retry the backups cleanup now... and wait til next day for the result !

[SansGuidon]

I'm ongoing a migration from Contabo to Hetzner storage (SSHFS) for the backup. I'll keep you posted.

[SansGuidon]

Switching to hetzner feels good enough for now . Full backup takes 30min for 21 apps. I've cancelled contabo storage service.
Hope this stays so snappy for the long run