Issue with Lengthy and Failing Updates

[archos]

Hi everyone,

I'm having trouble with updates on my system. Each update takes incredibly long, sometimes up to 10 hours, and yet it frequently fails.
I use Idrive bucket with rsync for performing updates. Even though I've attempted various adjustments and optimizations, issues with the speed and success of updates persist.

Here is the log output I've obtained when attempting to update:

box:shell backup-snapshot/app_cc8f455d-4285-4133-9234-9767a4977f23: /usr/bin/sudo -S -E --close-from=4 /home/yellowtent/box/src/scripts/backupupload.js snapshot/app_cc8f455d-4285-4133-9234-9767a4977f23 rsync {"localRoot":"/home/yellowtent/appsdata/cc8f455d-4285-4133-9234-9767a4977f23","layout":[]} errored BoxError: backup-snapshot/app_cc8f455d-4285-4133-9234-9767a4977f23 exited with code null signal SIGKILL
May 03 08:29:55 box:taskworker Task took 26992.838 seconds
May 03 08:29:55 box:tasks setCompleted - 9854: {"result":null,"error":{"stack":"BoxError: Backuptask crashed\n at runBackupUpload (/home/yellowtent/box/src/backuptask.js:163:15)\n at process.processTicksAndRejections (node:internal/process/task_queues:95:5)\n at async uploadAppSnapshot (/home/yellowtent/box/src/backuptask.js:360:5)\n at async backupAppWithTag (/home/yellowtent/box/src/backuptask.js:382:5)\n at async fullBackup (/home/yellowtent/box/src/backuptask.js:503:29)","name":"BoxError","reason":"Internal Error","details":{},"message":"Backuptask crashed"}}
May 03 08:29:55 box:tasks update 9854: {"percent":100,"result":null,"error":{"stack":"BoxError: Backuptask crashed\n at runBackupUpload (/home/yellowtent/box/src/backuptask.js:163:15)\n at process.processTicksAndRejections (node:internal/process/task_queues:95:5)\n at async uploadAppSnapshot (/home/yellowtent/box/src/backuptask.js:360:5)\n at async backupAppWithTag (/home/yellowtent/box/src/backuptask.js:382:5)\n at async fullBackup (/home/yellowtent/box/src/backuptask.js:503:29)","name":"BoxError","reason":"Internal Error","details":{},"message":"Backuptask crashed"}}
[no timestamp]  Backuptask crashed
[no timestamp]  }

Could you please advise me on how to address this issue? Thank you in advance for your assistance.

[nebulon]

Given that the backuptask got a SIGKILL maybe your system overall runs out of memory during the backup task and then gets killed by the kernel to avoid other instability on the system?

You should see related messages around that timestamp in the journalctl --system logs or dmesg if thats the case.

[archos]

Thanks for the reply, the dmesg was this log

[12574818.752159] memory: usage 6324224kB, limit 6324224kB, failcnt 82122340
[12574818.752160] memory+swap: usage 9640796kB, limit 9007199254740988kB, failcnt 0
[12574818.752161] kmem: usage 84016kB, limit 9007199254740988kB, failcnt 0
[12574818.752161] Memory cgroup stats for /system.slice/box-task-9854.service:
[12574818.752374] anon 6389710848
                  file 139264
                  kernel_stack 405504
                  slab 50835456
                  sock 0
                  shmem 0
                  file_mapped 135168
                  file_dirty 0
                  file_writeback 1486848
                  anon_thp 0
                  inactive_anon 798842880
                  active_anon 5591207936
                  inactive_file 319488
                  active_file 380928
                  unevictable 0
                  slab_reclaimable 43245568
                  slab_unreclaimable 7589888
                  pgfault 97424250
                  pgmajfault 69564
                  workingset_refault 38577
                  workingset_activate 5940
                  workingset_nodereclaim 293040
                  pgrefill 2032537
                  pgscan 83045423
                  pgsteal 81486428
                  pgactivate 463320
                  pgdeactivate 2028552
                  pglazyfree 0
                  pglazyfreed 0
                  thp_fault_alloc 0
                  thp_collapse_alloc 0
[12574818.752377] Tasks state (memory values in pages):
[12574818.752377] [  pid  ]   uid  tgid total_vm      rss pgtables_bytes swapents oom_score_adj name
[12574818.752384] [2031030]  1000 2031030   252834     6680  3022848    33976             0 node
[12574818.752387] [2317480]     0 2317480     2974      878    53248      186             0 sudo
[12574818.752391] [2317481]     0 2317481  2622067  1560113 31424512   799459             0 node
[12574818.752419] oom-kill:constraint=CONSTRAINT_MEMCG,nodemask=(null),cpuset=/,mems_allowed=0,oom_memcg=/system.slice/box-task-9854.service,task_memcg=/system.slice/box-task-9854.service,task=node,pid=2317481,uid=0
[12574818.752541] Memory cgroup out of memory: Killed process 2317481 (node) total-vm:10488268kB, anon-rss:6217956kB, file-rss:22504kB, shmem-rss:0kB, UID:0 pgtables:30688kB oom_score_adj:0

[girish]

@archos How much memory have you given the backup task ? Backups -> Configure -> Advanced. Maybe try increasing that a lot more.

[archos]

@girish Thank you for the response, I tried adding more memory. There was only 7 GB available for backup. I have another question, shouldn't rsync be uploading only changed files? For example, it uploads photos in Nextcloud and videos in Peertube every day anew."

[girish]

@archos yes, it should upload only changed files. Which backend are you using? If it's uploading every day again and again, it's most likely because it has never succeeded in previous attempts. Once, the first attempt succeeds, the future attempts won't re-upload.

[archos]

@girish Ok, thank you for the information. I use backup on IDrive e2. The backups are performed daily, but I only keep two. It's true that lately the backups have occasionally failed. I will try creating a new bucket and maybe now that I've added more memory, it will be better.

[archos]

@archos I added more memory for backups and created a new bucket. The first manually initiated backup went smoothly, but the second automatic one ended with 'Backup failed' again. I am attaching the log below. What's also strange is that the second backup again took 8 hours. I have set up the backups using Rsync, but it still re-uploads all videos, photos, books, etc., which is a tremendous amount of data—I have a total of 912 GB used. So, I'm not sure where the problem could be.
I also think that rsync uploads all the data from the server every day. This would match the size of the first bucket, which is 3.64 TB, even though I only keep two daily backups. I would be grateful for any advice.

box:tasks update 9868: {"percent":55.05405405405404,"message":"Copied 321629 files with error: null"}
May 04 07:20:32 box:tasks setCompleted - 9868: {"result":null,"error":{"stack":"BoxError: Backup not found\n at Object.setState (/home/yellowtent/box/src/backups.js:238:42)\n at process.processTicksAndRejections (node:internal/process/task_queues:95:5)\n at async rotateAppBackup (/home/yellowtent/box/src/backuptask.js:303:5)\n at async backupAppWithTag (/home/yellowtent/box/src/backuptask.js:383:12)\n at async fullBackup (/home/yellowtent/box/src/backuptask.js:503:29)","name":"BoxError","reason":"Not found","details":{},"message":"Backup not found"}}
May 04 07:20:32 box:tasks update 9868: {"percent":100,"result":null,"error":{"stack":"BoxError: Backup not found\n at Object.setState (/home/yellowtent/box/src/backups.js:238:42)\n at process.processTicksAndRejections (node:internal/process/task_queues:95:5)\n at async rotateAppBackup (/home/yellowtent/box/src/backuptask.js:303:5)\n at async backupAppWithTag (/home/yellowtent/box/src/backuptask.js:383:12)\n at async fullBackup (/home/yellowtent/box/src/backuptask.js:503:29)","name":"BoxError","reason":"Not found","details":{},"message":"Backup not found"}}
May 04 07:20:32 box:taskworker Task took 22829.343 seconds
[no timestamp]  Backup not found

[girish]

@archos strange... it says that it copied the files but after that it fails. If you reach out to us at support@cloudron.io , I can debug further.

[archos]

@girish I sent an email to support. Thank you very much.

[archos]

So two backups were completed successfully, but today the backup failed again. Mainly through rsync, it backs up the entire Cloudron each time, instead of incremental backups.
That seems strange to me.

May 07 07:30:11 box:tasks setCompleted - 9891: {"result":null,"error":{"stack":"BoxError: Backup not found\n at Object.setState (/home/yellowtent/box/src/backups.js:238:42)\n at process.processTicksAndRejections (node:internal/process/task_queues:95:5)\n at async rotateAppBackup (/home/yellowtent/box/src/backuptask.js:303:5)\n at async backupAppWithTag (/home/yellowtent/box/src/backuptask.js:383:12)\n at async fullBackup (/home/yellowtent/box/src/backuptask.js:503:29)","name":"BoxError","reason":"Not found","details":{},"message":"Backup not found"}}
May 07 07:30:11 box:tasks update 9891: {"percent":100,"result":null,"error":{"stack":"BoxError: Backup not found\n at Object.setState (/home/yellowtent/box/src/backups.js:238:42)\n at process.processTicksAndRejections (node:internal/process/task_queues:95:5)\n at async rotateAppBackup (/home/yellowtent/box/src/backuptask.js:303:5)\n at async backupAppWithTag (/home/yellowtent/box/src/backuptask.js:383:12)\n at async fullBackup (/home/yellowtent/box/src/backuptask.js:503:29)","name":"BoxError","reason":"Not found","details":{},"message":"Backup not found"}}
May 07 07:30:11 box:taskworker Task took 23409.098 seconds
[no timestamp]  Backup not found

[nebulon]

To update this thread. There seems to be a race where the backup cleaner kicks in while the full backup is still busy backing up apps. Those take a very long time so the cleaner already starts purging app backups from the database which then in the end cannot be referenced and thus the whole backup will error.

This will be good have fixed, currently testing a patch...

[archos]

@nebulon Thank you very much for attending to my issue.

[archos]

@nebulon Hello,
Unfortunately, the backup got stuck again today, this time during the Privatebin update. The update has not been completed since yesterday, and neither has the backup.

:database Connection 7252 error: Packets out of order. Got: 0 Expected: 2 PROTOCOL_PACKETS_OUT_OF_ORDER
May 14 10:12:21 box:database Connection 7258 error: Packets out of order. Got: 0 Expected: 2 PROTOCOL_PACKETS_OUT_OF_ORDER
May 14 10:12:21 box:database Connection 7256 error: Packets out of order. Got: 0 Expected: 2 PROTOCOL_PACKETS_OUT_OF_ORDER
May 14 10:12:21 box:database Connection 7253 error: Packets out of order. Got: 0 Expected: 2 PROTOCOL_PACKETS_OUT_OF_ORDER
May 14 10:12:21 box:database Connection 7255 error: Packets out of order. Got: 0 Expected: 2 PROTOCOL_PACKETS_OUT_OF_ORDER

[nebulon]

I was looking at it just now, so apparently backups have succeeded afterwards, however one backup run in this case takes around 5h. Since the backup does work on live-data for 5h a lot of things may interfere (like in this run database connection issues)... all this is of course not ideal, but the current strategy is to start all over again if it fails midway to avoid random state with the goal to eventually succeed.

This is of course no great answer for the moment. Not just specific to this, but 100s of Gb on top of various degrees of stable connections + remote storage protocols and endpoints which behave inconsistently in our experience (especially the lower cost they get) make this all not easy However there is much room to improve on our side with time.

Maybe we have to revisit this to look into other similar use-case setups how fine-grained and periodically other platforms deal with this, especially when cost per Gb or I/O is a factor.

[foliovision]

@nebulon said in Issue with Lengthy and Failing Updates:

This is of course no great answer for the moment. Not just specific to this, but 100s of Gb on top of various degrees of stable connections + remote storage protocols and endpoints which behave inconsistently in our experience (especially the lower cost they get) make this all not easy However there is much room to improve on our side with time.

Recommended solutions help. Backup works with this and this and this service. It's unreliable with that and that and that service.

Next big help would be for your backups to pace themselves for the long haul. You could pre-estimate size and refuse to run the backup in intervals which do not allow enough time to finish the backup (hourly, perhaps daily is not enough for some crazy Cloudroner with hundreds of gigabytes of data: we were just mailed by someone who uses our software with 260 TB of storage, argh, all at consumer level, not enterprise level).

Next you could cap backup speed not to max out the bandwidth for a working server.

Yes, there's lots Cloudron could do to make backups easier and more successful.

Ours fail all the time despite following guidelines. We had to manually remove 16GB of failed updates from our server (failed updates should autodelete), and then manually clean out NextCloud deleted files (which Cloudron could make automatic by default, even if NextCloud developers don't care about server space as they plan for dedicated servers and object space, our intrepid leaders at Cloudron could). And Cloudron didn't tell us we had to update from Ubuntu 18 LTS for backups and updates to work properly so we were caught in a closed loop. It's not easy setting up a service as complex as Cloudron but there is some low-hanging fruit here.

[archos]

@nebulon Hello, thank you for the information. I find it odd why Rsync always backs up all the files. Yes, the first backup is large, but afterwards, only the changed files should be backed up, not all the videos from Peertube and many GB from Nextcloud every day. I've tried several backup services, kept two-day and four-week backups, but Rsync always backs up the entire server each time. That's why I now keep only two backups. I use Rsync on another server as well, and there is no problem there.
That's why the backups are slow when the server backs up almost 1 TB of data daily.

[necrevistonnezr]

@archos said in Issue with Lengthy and Failing Updates:

@nebulon Hello, thank you for the information. I find it odd why Rsync always backs up all the files. Yes, the first backup is large, but afterwards, only the changed files should be backed up, not all the videos from Peertube and many GB from Nextcloud every day.

Are you sure those files that seem identical but are copied regardless are not modified in any way? Other timestamps for example?

[archos]

@necrevistonnezr The server occupies 960.45 GB and I currently maintain only two backups, with a total size of 2 TB. The attached image shows the log from today's backup of the Calibre application. I uploaded books to this library about two years ago. Since then, I haven't uploaded any new books to Calibre and no one else has made any changes, yet every day, the entire 10 GB of books is being backed up. It doesn't make sense for the two backups to occupy 2 TB when the server itself only uses nearly 1 TB.

[necrevistonnezr]

I would recommend to investigate whether the same files in the app and in the backup are indeed identical.
rsync would not copy identical files all over again.
I use rsync to backup to an external harddrive - my Cloudron instance is around ~ 250 GB and all my backups (7 daily, 4 weekly, 12 monthly) going back to June 2023 occupy ~ 350 GB.
The same backups that I push via restic to Onedrive going back to June 2022 (!) occupy ~ 310 GB (restic is very good in compression and de-duplication).