Backups : regular crash

[timconsidine]

There is an upcoming change at Scaleway ... but it hasn't happened yet ... and may have no impact anyway.

https://t.elements.scaleway.com/c/?t=def12f9-4mc-el8c-503-!8xq!

[girish]

I haven't managed to reproduce this one yet. But this looks like some intermittent upstream issue.

[marcom]

affected by the same problem, also using scaleway.
Did anyone found a solution or workaround?

[timconsidine]

@marcom I changed the time of my backups from 4am to 6am and saw some improvement.
Still not 100% but better
I need to experiment a little more.
Maybe Scaleway are doing something 2am-5am ?
Or (as suggested by someone) everyone else is doing backups then

[jdaviescoates]

I wonder if tuning concurrency settings could help here?

https://docs.cloudron.io/backups/#concurrency-settings

Or filename lenghs?

https://docs.cloudron.io/backups/#filenames

Or changing the part size?

Or giving the back up process more memory?

The latter two I was unable to find documented in the Cloudron docs (possibly just because I'm on my phone)

[girish]

@marcom What is the error you are seeing in the logs?

[marcom]

@timconsidine thanks for your sugestion, I changed it to 5:00 lets see if something changes!

[marcom]

@jdaviescoates Thanks for your suggestion, I changed the memory size to 4 GB and the chunk size to 256Mb lets see if it succeeds.

[marcom]

@girish most likely a timeout, because of the size of the nextcloud backup?

 throw er; // Unhandled 'error' event
at WriteWrap.onWriteComplete [as oncomplete] (node:internal/stream_base_commons:94:16)
at async backupAppWithTag (/home/yellowtent/box/src/backuptask.js:386:5)
at async fullBackup (/home/yellowtent/box/src/backuptask.js:507:29)
at async uploadAppSnapshot (/home/yellowtent/box/src/backuptask.js:364:5)
at emitErrorCloseNT (node:internal/streams/destroy:116:3)
at emitErrorNT (node:internal/streams/destroy:151:8)
at process.processTicksAndRejections (node:internal/process/task_queues:82:21) {
at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
at runBackupUpload (/home/yellowtent/box/src/backuptask.js:167:15)
code: 'EPIPE',
errno: -32,
syscall: 'write'
Jul 30 23:00:04 box:shell backup-snapshot/app_3fcd8ed1-28c2-4773-9a8c-0a4b7b9ec512 (stderr): 2023-07-30T21:00:04.932Z box:settings initCache: pre-load settings
Jul 30 23:00:04 box:shell backup-snapshot/app_3fcd8ed1-28c2-4773-9a8c-0a4b7b9ec512 (stderr): 2023-07-30T21:00:04.943Z box:backuptask upload: path snapshot/app_3fcd8ed1-28c2-4773-9a8c-0a4b7b9ec512 format tgz dataLayout {"localRoot":"/home/yellowtent/appsdata/3fcd8ed1-28c2-4773-9a8c-0a4b7b9ec512","layout":[]}
Jul 30 23:00:05 box:backuptask checkPreconditions: getting disk usage of /home/yellowtent/appsdata/3fcd8ed1-28c2-4773-9a8c-0a4b7b9ec512
Jul 30 23:00:05 box:shell backup-snapshot/app_3fcd8ed1-28c2-4773-9a8c-0a4b7b9ec512 (stderr): 2023-07-30T21:00:05.126Z box:backuptask upload: mount point status is {"state":"active"}
Jul 30 23:00:05 box:shell backup-snapshot/app_3fcd8ed1-28c2-4773-9a8c-0a4b7b9ec512 (stderr): 2023-07-30T21:00:05.136Z box:backuptask checkPreconditions: total required =554856 available=undefined
Jul 30 23:00:05 box:shell backup-snapshot/app_3fcd8ed1-28c2-4773-9a8c-0a4b7b9ec512 (stderr): 2023-07-30T21:00:05.137Z box:backupformat/tgz upload: Uploading {"localRoot":"/home/yellowtent/appsdata/3fcd8ed1-28c2-4773-9a8c-0a4b7b9ec512","layout":[]} to snapshot/app_3fcd8ed1-28c2-4773-9a8c-0a4b7b9ec512
Jul 30 23:00:06 box:shell backup-snapshot/app_3fcd8ed1-28c2-4773-9a8c-0a4b7b9ec512 (stderr): 2023-07-30T21:00:06.526Z box:storage/s3 Uploaded cloudron/snapshot/app_3fcd8ed1-28c2-4773-9a8c-0a4b7b9ec512.tar.gz with partSize 104857600: {"ETag":"....","VersionId":"1690750805386990","Location":"https://url.s3.fr-par.scw.cloud/ ..."}
Jul 30 23:00:06 box:shell backup-snapshot/app_3fcd8ed1-28c2-4773-9a8c-0a4b7b9ec512 (stderr): 2023-07-30T21:00:06.527Z box:backupupload upload completed. error: null
Jul 30 23:00:06 box:backuptask runBackupUpload: result - {"result":""}
Jul 30 23:00:06 box:backuptask uploadAppSnapshot: chat.myServer.url uploaded to snapshot/app_3fcd8ed1-28c2-4773-9a8c-0a4b7b9ec512. 2.123 seconds
Jul 30 23:00:06 box:backuptask rotateAppBackup: rotating chat.myServer.url to path 2023-07-30-210000-638/app_chat.myServer.url_v1.18.2
Jul 30 23:00:06 box:tasks update 8200: {"percent":17.666666666666668,"message":"Copying with concurrency of 10"}
Jul 30 23:00:06 box:tasks update 8200: {"percent":17.666666666666668,"message":"Copying files from 0-1"}
Jul 30 23:00:06 box:tasks update 8200: {"percent":17.666666666666668,"message":"Copying cloudron/snapshot/app_3fcd8ed1-28c2-4773-9a8c-0a4b7b9ec512.tar.gz"}
Jul 30 23:00:07 box:backuptask copy: copied successfully to 2023-07-30-210000-638/app_chat.myServer.url_v1.18.2. Took 0.992 seconds
Jul 30 23:00:07 box:tasks update 8200: {"percent":17.666666666666668,"message":"Copied 1 files with error: null"}
Jul 30 23:00:07 box:backuptask fullBackup: app chat.myServer.url backup finished. Took 3.535 seconds
Jul 30 23:00:07 box:tasks update 8200: {"percent":17.666666666666668,"message":"Backing up nexcloud.myServer.url (3/9)"}
Jul 30 23:00:07 box:tasks update 8200: {"percent":26,"message":"Snapshotting app nexcloud.myServer.url"}
Jul 30 23:00:07 box:services Backing up postgresql
Jul 30 23:00:07 box:services backupAddons
Jul 30 23:00:07 box:services backupAddons: backing up ["postgresql","sendmail","ldap","redis","localstorage","scheduler","turn"]
Jul 30 23:00:07 box:services pipeRequestToFile: connected with status code 200
Jul 30 23:00:08 box:services Backing up redis
Jul 30 23:00:08 box:services pipeRequestToFile: connected with status code 200
Jul 30 23:00:09 box:backuptask snapshotApp: nexcloud.myServer.url took 1.512 seconds
Jul 30 23:00:09 box:tasks update 8200: {"percent":26,"message":"Uploading app snapshot nexcloud.myServer.url"}
Jul 30 23:00:09 box:shell backup-snapshot/app_46bcff51-7325-4e7a-8830-7cac3308978c spawn: /usr/bin/sudo -S -E --close-from=4 /home/yellowtent/box/src/scripts/backupupload.js snapshot/app_46bcff51-7325-4e7a-8830-7cac3308978c tgz {"localRoot":"/home/yellowtent/appsdata/46bcff51-7325-4e7a-8830-7cac3308978c","layout":[]}
Jul 30 23:00:09 box:shell backup-snapshot/app_46bcff51-7325-4e7a-8830-7cac3308978c (stderr): 2023-07-30T21:00:09.525Z box:backupupload Backing up {"localRoot":"/home/yellowtent/appsdata/46bcff51-7325-4e7a-8830-7cac3308978c","layout":[]} to snapshot/app_46bcff51-7325-4e7a-8830-7cac3308978c
Jul 30 23:00:09 box:shell backup-snapshot/app_46bcff51-7325-4e7a-8830-7cac3308978c (stderr): 2023-07-30T21:00:09.553Z box:settings initCache: pre-load settings
Jul 30 23:00:09 box:shell backup-snapshot/app_46bcff51-7325-4e7a-8830-7cac3308978c (stderr): 2023-07-30T21:00:09.564Z box:backuptask upload: path snapshot/app_46bcff51-7325-4e7a-8830-7cac3308978c format tgz dataLayout {"localRoot":"/home/yellowtent/appsdata/46bcff51-7325-4e7a-8830-7cac3308978c","layout":[]}
Jul 30 23:00:09 box:shell backup-snapshot/app_46bcff51-7325-4e7a-8830-7cac3308978c (stderr): 2023-07-30T21:00:09.727Z box:backuptask checkPreconditions: getting disk usage of /home/yellowtent/appsdata/46bcff51-7325-4e7a-8830-7cac3308978c
Jul 30 23:00:09 box:shell backup-snapshot/app_46bcff51-7325-4e7a-8830-7cac3308978c (stderr): 2023-07-30T21:00:09.727Z box:backuptask upload: mount point status is {"state":"active"}
Jul 30 23:00:09 box:backupformat/tgz upload: Uploading {"localRoot":"/home/yellowtent/appsdata/46bcff51-7325-4e7a-8830-7cac3308978c","layout":[]} to snapshot/app_46bcff51-7325-4e7a-8830-7cac3308978c
Jul 30 23:00:09 box:shell backup-snapshot/app_46bcff51-7325-4e7a-8830-7cac3308978c (stderr): 2023-07-30T21:00:09.949Z box:backuptask checkPreconditions: total required =11237224563 available=undefined
Jul 30 23:00:19 box:tasks update 8200: {"percent":26,"message":"Uploading backup 169M@17MBps (nexcloud.myServer.url)"}
Jul 30 23:00:29 box:tasks update 8200: {"percent":26,"message":"Uploading backup 385M@22MBps (nexcloud.myServer.url)"}
Jul 30 23:00:40 box:tasks update 8200: {"percent":26,"message":"Uploading backup 600M@21MBps (nexcloud.myServer.url)"}
Jul 30 23:00:50 box:tasks update 8200: {"percent":26,"message":"Uploading backup 790M@19MBps (nexcloud.myServer.url)"}
Jul 30 23:01:00 box:tasks update 8200: {"percent":26,"message":"Uploading backup 856M@7MBps (nexcloud.myServer.url)"}
Jul 30 23:01:10 box:tasks update 8200: {"percent":26,"message":"Uploading backup 916M@6MBps (nexcloud.myServer.url)"}
Jul 30 23:01:20 box:tasks update 8200: {"percent":26,"message":"Uploading backup 1045M@13MBps (nexcloud.myServer.url)"}
Jul 30 23:01:30 box:tasks update 8200: {"percent":26,"message":"Uploading backup 1229M@18MBps (nexcloud.myServer.url)"}
Jul 30 23:01:40 box:tasks update 8200: {"percent":26,"message":"Uploading backup 1427M@20MBps (nexcloud.myServer.url)"}
Jul 30 23:01:50 box:tasks update 8200: {"percent":26,"message":"Uploading backup 1616M@19MBps (nexcloud.myServer.url)"}
Jul 30 23:02:00 box:tasks update 8200: {"percent":26,"message":"Uploading backup 1806M@19MBps (nexcloud.myServer.url)"}
Jul 30 23:02:10 box:tasks update 8200: {"percent":26,"message":"Uploading backup 1988M@18MBps (nexcloud.myServer.url)"}
Jul 30 23:02:20 box:tasks update 8200: {"percent":26,"message":"Uploading backup 2191M@20MBps (nexcloud.myServer.url)"}
Jul 30 23:02:30 box:tasks update 8200: {"percent":26,"message":"Uploading backup 2374M@18MBps (nexcloud.myServer.url)"}
Jul 30 23:02:40 box:tasks update 8200: {"percent":26,"message":"Uploading backup 2563M@19MBps (nexcloud.myServer.url)"}
Jul 30 23:02:50 box:tasks update 8200: {"percent":26,"message":"Uploading backup 2757M@19MBps (nexcloud.myServer.url)"}
Jul 30 23:03:00 box:tasks update 8200: {"percent":26,"message":"Uploading backup 2978M@22MBps (nexcloud.myServer.url)"}
Jul 30 23:03:10 box:tasks update 8200: {"percent":26,"message":"Uploading backup 3180M@20MBps (nexcloud.myServer.url)"}
Jul 30 23:03:20 box:tasks update 8200: {"percent":26,"message":"Uploading backup 3407M@23MBps (nexcloud.myServer.url)"}
Jul 30 23:03:30 box:tasks update 8200: {"percent":26,"message":"Uploading backup 3636M@23MBps (nexcloud.myServer.url)"}
Jul 30 23:03:40 box:tasks update 8200: {"percent":26,"message":"Uploading backup 3855M@22MBps (nexcloud.myServer.url)"}
Jul 30 23:03:50 box:tasks update 8200: {"percent":26,"message":"Uploading backup 4057M@20MBps (nexcloud.myServer.url)"}
Jul 30 23:04:00 box:tasks update 8200: {"percent":26,"message":"Uploading backup 4279M@22MBps (nexcloud.myServer.url)"}
Jul 30 23:04:10 box:tasks update 8200: {"percent":26,"message":"Uploading backup 4495M@22MBps (nexcloud.myServer.url)"}
Jul 30 23:04:20 box:tasks update 8200: {"percent":26,"message":"Uploading backup 4694M@20MBps (nexcloud.myServer.url)"}
Jul 30 23:04:24 box:shell backup-snapshot/app_46bcff51-7325-4e7a-8830-7cac3308978c (stderr): node:events:491
Jul 30 23:04:25 box:shell backup-snapshot/app_46bcff51-7325-4e7a-8830-7cac3308978c code: 1, signal: null
Jul 30 23:04:25 box:tasks setCompleted - 8200: {"result":null,"error":{"stack":"BoxError: Backuptask crashed\n at runBackupUpload (/home/yellowtent/box/src/backuptask.js:167:15)\n at process.processTicksAndRejections (node:internal/process/task_queues:95:5)\n at async uploadAppSnapshot (/home/yellowtent/box/src/backuptask.js:364:5)\n at async backupAppWithTag (/home/yellowtent/box/src/backuptask.js:386:5)\n at async fullBackup (/home/yellowtent/box/src/backuptask.js:507:29)","name":"BoxError","reason":"Internal Error","details":{},"message":"Backuptask crashed"}}
Jul 30 23:04:25 box:tasks update 8200: {"percent":100,"result":null,"error":{"stack":"BoxError: Backuptask crashed\n at runBackupUpload (/home/yellowtent/box/src/backuptask.js:167:15)\n at process.processTicksAndRejections (node:internal/process/task_queues:95:5)\n at async uploadAppSnapshot (/home/yellowtent/box/src/backuptask.js:364:5)\n at async backupAppWithTag (/home/yellowtent/box/src/backuptask.js:386:5)\n at async fullBackup (/home/yellowtent/box/src/backuptask.js:507:29)","name":"BoxError","reason":"Internal Error","details":{},"message":"Backuptask crashed"}}
Jul 30 23:04:25 box:taskworker Task took 264.414 seconds
Backuptask crashed
'error' event on TLSSocket instance at:
write EPIPE
v18.16.0

[marcom]

Thanks for all your suggestions. The manually started job finished now.
Lets see if the scheduled will succeed.

[marcom]

Most of the time the scheduled backups now succeed, but not always.
I'll keep an eye on the backups and make manual backups if the scheduled failed.

Let's see if the changes of scaleway improve the situation.

Thanks again for the suggestions and help.