Backups have failed ever since moving some apps to a volume

[omen]

Three months ago I added a volume and moved some of my apps to it. Ever since, the backups will begin, run through the list of apps on the main machine, and once it gets to the apps on the volume, it just hangs forever.

I've tried adjusting the backup settings (increased memory, adjusted part size and concurrency, tried rsync instead of tar, etc), but nothing has any effect.

Here are the logs (anonymized):

backup 
Mar 14 01:27:55 box:shell backup-snapshot/app_3c73a834-a6c1-456c-82e5-aba344e33bd9 (stdout): 2023-03-14T05:27:55.389Z box:backupformat/rsync Uploaded fsmetadata.json
Mar 14 01:27:55 box:shell backup-snapshot/app_3c73a834-a6c1-456c-82e5-aba344e33bd9 (stdout): 2023-03-14T05:27:55.391Z box:storage/s3 Uploaded snapshot/app_3c73a834-a6c1-456c-82e5-aba344e33bd9/config.json with partSize 262144000: {"ETag":"\"f2739d7fce585f9db66adf3c2cc53f00\"","Location":"https://mybusiness-cloudron.sfo3.digitaloceanspaces.com/snapshot/app_3c73a834-a6c1-456c-82e5-aba344e33bd9/config.json","key":"snapshot/app_3c73a834-a6c1-456c-82e5-aba344e33bd9/config.json","Key":"snapshot/app_3c73a834-a6c1-456c-82e5-aba344e33bd9/config.json","Bucket":"mybusiness-cloudron"}
Mar 14 01:27:55 box:shell backup-snapshot/app_3c73a834-a6c1-456c-82e5-aba344e33bd9 (stdout): 2023-03-14T05:27:55.391Z box:backupformat/rsync Uploaded config.json
Mar 14 01:27:55 box:syncer Done processing adds. error: null
Mar 14 01:27:55 box:shell backup-snapshot/app_3c73a834-a6c1-456c-82e5-aba344e33bd9 (stdout): 2023-03-14T05:27:55.392Z box:backupupload upload completed. error: null
Mar 14 01:27:55 box:backuptask runBackupUpload: result - {"result":""}
Mar 14 01:27:55 box:backuptask uploadAppSnapshot: docs.mydomain.com uploaded to snapshot/app_3c73a834-a6c1-456c-82e5-aba344e33bd9. 0.843 seconds
Mar 14 01:27:55 box:backuptask rotateAppBackup: rotating docs.mydomain.com to path 2023-03-14-052719-342/app_docs.mydomain.com_v5.17.9
Mar 14 01:27:55 box:tasks update 3979: {"percent":19.51851851851852,"message":"Copying with concurrency of 10"}
Mar 14 01:27:55 box:tasks update 3979: {"percent":19.51851851851852,"message":"Copying files from 0-4"}
Mar 14 01:27:55 box:tasks update 3979: {"percent":19.51851851851852,"message":"Copying config.json"}
Mar 14 01:27:55 box:tasks update 3979: {"percent":19.51851851851852,"message":"Copying data/.surfer.json"}
Mar 14 01:27:55 box:tasks update 3979: {"percent":19.51851851851852,"message":"Copying data/tokens.json"}
Mar 14 01:27:55 box:tasks update 3979: {"percent":19.51851851851852,"message":"Copying fsmetadata.json"}
Mar 14 01:27:55 box:tasks update 3979: {"percent":19.51851851851852,"message":"Copied 4 files with error: null"}
Mar 14 01:27:55 box:backuptask copy: copied successfully to 2023-03-14-052719-342/app_docs.mydomain.com_v5.17.9. Took 0.078 seconds
Mar 14 01:27:55 box:backuptask fullBackup: app docs.mydomain.com backup finished. Took 0.938 seconds
Mar 14 01:27:55 box:tasks update 3979: {"percent":19.51851851851852,"message":"Backing up share.mydomain.com (6/24)"}
Mar 14 01:27:55 box:tasks update 3979: {"percent":23.22222222222222,"message":"Snapshotting app share.mydomain.com"}
Mar 14 01:27:55 box:services backupAddons
Mar 14 01:27:55 box:services backupAddons: backing up ["localstorage","scheduler"]
Mar 14 01:27:55 box:backuptask snapshotApp: share.mydomain.com took 0.002 seconds
Mar 14 01:27:55 box:tasks update 3979: {"percent":23.22222222222222,"message":"Uploading app snapshot share.mydomain.com"}
Mar 14 01:27:55 box:backuptask runBackupUpload: adjusting heap size to 3840M
Mar 14 01:27:55 box:shell backup-snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5 spawn: /usr/bin/sudo -S -E --close-from=4 /home/yellowtent/box/src/scripts/backupupload.js snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5 rsync {"localRoot":"/home/yellowtent/appsdata/402b058d-d0cc-212d-abcd-43ba7ca1b5c5","layout":[]}
Mar 14 01:27:55 box:shell backup-snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5 (stdout): 2023-03-14T05:27:55.981Z box:backupupload Backing up {"localRoot":"/home/yellowtent/appsdata/402b058d-d0cc-212d-abcd-43ba7ca1b5c5","layout":[]} to snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5
Mar 14 01:27:56 box:shell backup-snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5 (stdout): 2023-03-14T05:27:56.019Z box:settings initCache: pre-load settings
Mar 14 01:27:56 box:shell backup-snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5 (stdout): 2023-03-14T05:27:56.030Z box:backuptask upload: path snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5 format rsync dataLayout {"localRoot":"/home/yellowtent/appsdata/402b058d-d0cc-212d-abcd-43ba7ca1b5c5","layout":[]}
Mar 14 01:27:56 box:shell backup-snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5 (stdout): 2023-03-14T05:27:56.184Z box:backuptask upload: mount point status is {"state":"active"}
Mar 14 01:27:56 box:shell backup-snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5 (stdout): 2023-03-14T05:27:56.184Z box:backuptask checkPreconditions: getting disk usage of /home/yellowtent/appsdata/402b058d-d0cc-212d-abcd-43ba7ca1b5c5
Mar 14 01:27:56 box:shell backup-snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5 (stdout): 2023-03-14T05:27:56.197Z box:backuptask checkPreconditions: total required =33915 available=undefined
Mar 14 01:27:56 box:shell backup-snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5 (stdout): 2023-03-14T05:27:56.226Z box:syncer Processing 0 deletes and 2 additions
Mar 14 01:27:56 box:shell backup-snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5 (stdout): 2023-03-14T05:27:56.226Z box:syncer Done processing deletes. error: null
Mar 14 01:27:56 box:shell backup-snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5 (stdout): 2023-03-14T05:27:56.227Z box:backupformat/rsync sync: processing task: {"operation":"add","path":"config.json","reason":"changed","position":0}
Mar 14 01:27:56 box:tasks update 3979: {"percent":23.22222222222222,"message":"Adding config.json (share.mydomain.com)"}
Mar 14 01:27:56 box:shell backup-snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5 (stdout): 2023-03-14T05:27:56.228Z box:backupformat/rsync Adding config.json position 0 try 1
Mar 14 01:27:56 box:shell backup-snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5 (stdout): 2023-03-14T05:27:56.229Z box:backupformat/rsync sync: processing task: {"operation":"add","path":"fsmetadata.json","reason":"changed","position":1}
Mar 14 01:27:56 box:shell backup-snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5 (stdout): 2023-03-14T05:27:56.229Z box:backupformat/rsync Adding fsmetadata.json position 1 try 1
Mar 14 01:27:56 box:shell backup-snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5 (stdout): 2023-03-14T05:27:56.299Z box:storage/s3 Uploaded snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5/config.json with partSize 262144000: {"ETag":"\"601cf74639592c7a8869f487154cf926\"","Location":"https://mybusiness-cloudron.sfo3.digitaloceanspaces.com/snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5/config.json","key":"snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5/config.json","Key":"snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5/config.json","Bucket":"mybusiness-cloudron"}
Mar 14 01:27:56 box:shell backup-snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5 (stdout): 2023-03-14T05:27:56.299Z box:backupformat/rsync Uploaded config.json
Mar 14 01:27:56 box:shell backup-snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5 (stdout): 2023-03-14T05:27:56.301Z box:storage/s3 Uploaded snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5/fsmetadata.json with partSize 262144000: {"ETag":"\"ab5df670d439153d0a9cf7a3485987af\"","Location":"https://mybusiness-cloudron.sfo3.digitaloceanspaces.com/snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5/fsmetadata.json","key":"snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5/fsmetadata.json","Key":"snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5/fsmetadata.json","Bucket":"mybusiness-cloudron"}
Mar 14 01:27:56 box:shell backup-snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5 (stdout): 2023-03-14T05:27:56.301Z box:backupformat/rsync Uploaded fsmetadata.json
Mar 14 01:27:56 box:shell backup-snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5 (stdout): 2023-03-14T05:27:56.301Z box:syncer Done processing adds. error: null
Mar 14 01:27:56 box:shell backup-snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5 (stdout): 2023-03-14T05:27:56.301Z box:backupupload upload completed. error: null
Mar 14 01:27:56 box:backuptask runBackupUpload: result - {"result":""}
Mar 14 01:27:56 box:backuptask uploadAppSnapshot: share.mydomain.com uploaded to snapshot/app_402b058d-d0cc-212d-abcd-43ba7ca1b5c5. 0.813 seconds
Mar 14 01:27:56 box:backuptask rotateAppBackup: rotating share.mydomain.com to path 2023-03-14-052719-342/app_share.mydomain.com_v1.6.1
Mar 14 01:27:56 box:tasks update 3979: {"percent":23.22222222222222,"message":"Copying with concurrency of 10"}
Mar 14 01:27:56 box:tasks update 3979: {"percent":23.22222222222222,"message":"Copying files from 0-4"}
Mar 14 01:27:56 box:tasks update 3979: {"percent":23.22222222222222,"message":"Copying config.json"}
Mar 14 01:27:56 box:tasks update 3979: {"percent":23.22222222222222,"message":"Copying data/custom.php"}
Mar 14 01:27:56 box:tasks update 3979: {"percent":23.22222222222222,"message":"Copying data/php.ini"}
Mar 14 01:27:56 box:tasks update 3979: {"percent":23.22222222222222,"message":"Copying fsmetadata.json"}
Mar 14 01:27:56 box:tasks update 3979: {"percent":23.22222222222222,"message":"Copied 4 files with error: null"}
Mar 14 01:27:56 box:backuptask copy: copied successfully to 2023-03-14-052719-342/app_share.mydomain.com_v1.6.1. Took 0.067 seconds
Mar 14 01:27:56 box:backuptask fullBackup: app share.mydomain.com backup finished. Took 0.893 seconds
Mar 14 01:27:56 box:tasks update 3979: {"percent":23.22222222222222,"message":"Backing up mybusiness.com (7/24)"}
Mar 14 01:27:56 box:tasks update 3979: {"percent":26.925925925925924,"message":"Snapshotting app mybusiness.com"}
Mar 14 01:27:56 box:services backupAddons
Mar 14 01:27:56 box:services backupAddons: backing up ["mysql","localstorage","sendmail","ldap","scheduler"]
Mar 14 01:27:56 box:services Backing up mysql
Mar 14 01:27:56 box:services pipeRequestToFile: connected with status code 200
Mar 14 01:27:56 box:backuptask snapshotApp: mybusiness.com took 0.451 seconds
Mar 14 01:27:56 box:tasks update 3979: {"percent":26.925925925925924,"message":"Uploading app snapshot mybusiness.com"}
Mar 14 01:27:56 box:backuptask runBackupUpload: adjusting heap size to 3840M
Mar 14 01:27:56 box:shell backup-snapshot/app_46cc3d4d-9761-45ad-9582-98083436a8a6 spawn: /usr/bin/sudo -S -E --close-from=4 /home/yellowtent/box/src/scripts/backupupload.js snapshot/app_46cc3d4d-9761-45ad-9582-98083436a8a6 rsync {"localRoot":"/home/yellowtent/appsdata/46cc3d4d-9761-45ad-9582-98083436a8a6","layout":[{"localDir":"/mnt/volumes/a2a24da5a9a1f4384d7e1b46042b3b2f/mybusiness","remoteDir":"data"}]}
Mar 14 01:27:57 box:shell backup-snapshot/app_46cc3d4d-9761-45ad-9582-98083436a8a6 (stdout): 2023-03-14T05:27:57.317Z box:backupupload Backing up {"localRoot":"/home/yellowtent/appsdata/46cc3d4d-9761-45ad-9582-98083436a8a6","layout":[{"localDir":"/mnt/volumes/a2a24da5a9a1f4384d7e1b46042b3b2f/mybusiness","remoteDir":"data"}]} to snapshot/app_46cc3d4d-9761-45ad-9582-98083436a8a6
Mar 14 01:27:57 box:shell backup-snapshot/app_46cc3d4d-9761-45ad-9582-98083436a8a6 (stdout): 2023-03-14T05:27:57.356Z box:settings initCache: pre-load settings
Mar 14 01:27:57 box:shell backup-snapshot/app_46cc3d4d-9761-45ad-9582-98083436a8a6 (stdout): 2023-03-14T05:27:57.371Z box:backuptask upload: path snapshot/app_46cc3d4d-9761-45ad-9582-98083436a8a6 format rsync dataLayout {"localRoot":"/home/yellowtent/appsdata/46cc3d4d-9761-45ad-9582-98083436a8a6","layout":[{"localDir":"/mnt/volumes/a2a24da5a9a1f4384d7e1b46042b3b2f/mybusiness","remoteDir":"data"}]}
Mar 14 01:27:57 box:shell backup-snapshot/app_46cc3d4d-9761-45ad-9582-98083436a8a6 (stdout): 2023-03-14T05:27:57.549Z box:backuptask upload: mount point status is {"state":"active"}
Mar 14 01:27:57 box:shell backup-snapshot/app_46cc3d4d-9761-45ad-9582-98083436a8a6 (stdout): 2023-03-14T05:27:57.549Z box:backuptask checkPreconditions: getting disk usage of /home/yellowtent/appsdata/46cc3d4d-9761-45ad-9582-98083436a8a6
Mar 14 01:27:57 box:shell backup-snapshot/app_46cc3d4d-9761-45ad-9582-98083436a8a6 (stdout): 2023-03-14T05:27:57.557Z box:backuptask checkPreconditions: getting disk usage of /mnt/volumes/a2a24da5a9a1f4384d7e1b46042b3b2f/mybusiness

Here is my current backup config:

{
    "remotePath": "2022-12-05-040001-253/box_v7.3.4",
    "encrypted": false,
    "provider": "digitalocean-spaces",
    "format": "rsync",
    "memoryLimit": 4294967296,
    "schedulePattern": "00 00 23 * * *",
    "retentionPolicy": {
        "keepWithinSecs": 172800
    },
    "bucket": "mybusiness-cloudron",
    "prefix": "",
    "accessKeyId": "XXXXXXXXXXXXXXXXXXXXX",
    "endpoint": "https://sfo3.digitaloceanspaces.com",
    "region": "us-east-1",
    "uploadPartSize": 262144000,
    "downloadConcurrency": 10,
    "syncConcurrency": 20,
    "copyConcurrency": 10,
    "encryption": null
}

Any recommendations? This is getting frustrating. 3 months with only a portion of my apps backed up automatically.

Running on Cloudron 7.3.4, and can't update due to failure with backups.

[girish]

@omen said in Backups have failed ever since moving some apps to a volume:

Mar 14 01:27:57 box:shell backup-snapshot/app_46cc3d4d-9761-45ad-9582-98083436a8a6 (stdout): 2023-03-14T05:27:57.557Z box:backuptask checkPreconditions: getting disk usage of /mnt/volumes/a2a24da5a9a1f4384d7e1b46042b3b2f/mybusiness

It seems it's unable to get the disk usage. Can you check if du -Dsb /mnt/volumes/a2a24da5a9a1f4384d7e1b46042b3b2f/mybusiness works ?

[omen]

@girish Nope. After hitting <enter> it just sits there indefinitely (or at least as long as I was willing to sit waiting...)

[omen]

@omen I can navigate through the volume in the shell just fine, and the apps themselves are working. They just don't back up. How strange that du isn't working correctly

[omen]

@girish Your question got me wondering what was going on.

Turns out, two apps on the volume both had caches that were insane (one due to an old uninstalled WP cache plugin that was removed, but maintained its 12 MILLION cached files, and the other was Mastodon, which needed some manual cleaning for the 800k files it had cached).

Turns out there were just SO MANY folders/files that any attempt to backup or read the size would just time out.

D'oh!