Backup failing (flaky CIFS mount)

jdaviescoates

I got this notification:

Backup failed: Unknown system error -128: Unknown system error -128, mkdir. Logs are available here.

Here are the logs:

Dec 24 03:51:13 box:backupupload v8 heap : used 31653696 total: 43773952 max: 1526909922
Dec 24 03:51:21 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 27187M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:51:31 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 27236M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:51:41 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 27267M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:51:43 box:shell backup-snapshot/app_d0e0fa7c-e358-4d93-869b-e227feec349f (stdout): 2020-12-24T03:51:43.905Z box:backupupload process: rss: 42160128 heapTotal: 43773952 heapUsed: 32011952 external: 5064058
Dec 24 03:51:43 box:shell backup-snapshot/app_d0e0fa7c-e358-4d93-869b-e227feec349f (stdout): 2020-12-24T03:51:43.908Z box:backupupload v8 heap : used 32012088 total: 43773952 max: 1526909922
Dec 24 03:51:51 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 27296M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:52:01 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 27335M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:52:11 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 27383M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:52:13 box:shell backup-snapshot/app_d0e0fa7c-e358-4d93-869b-e227feec349f (stdout): 2020-12-24T03:52:13.895Z box:backupupload process: rss: 61669376 heapTotal: 42725376 heapUsed: 30804040 external: 4619642
Dec 24 03:52:13 box:shell backup-snapshot/app_d0e0fa7c-e358-4d93-869b-e227feec349f (stdout): 2020-12-24T03:52:13.895Z box:backupupload v8 heap : used 30804176 total: 42725376 max: 1526909922
Dec 24 03:52:21 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 27435M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:52:31 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 27485M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:52:41 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 27516M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:52:43 box:shell backup-snapshot/app_d0e0fa7c-e358-4d93-869b-e227feec349f (stdout): 2020-12-24T03:52:43.904Z box:backupupload process: rss: 38522880 heapTotal: 41152512 heapUsed: 30619232 external: 7814522
Dec 24 03:52:43 box:shell backup-snapshot/app_d0e0fa7c-e358-4d93-869b-e227feec349f (stdout): 2020-12-24T03:52:43.912Z box:backupupload v8 heap : used 30619368 total: 41152512 max: 1526909922
Dec 24 03:52:51 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 27549M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:53:01 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 27594M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:53:11 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 27642M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:53:13 box:shell backup-snapshot/app_d0e0fa7c-e358-4d93-869b-e227feec349f (stdout): 2020-12-24T03:53:13.897Z box:backupupload process: rss: 62439424 heapTotal: 41152512 heapUsed: 30215640 external: 11222906
Dec 24 03:53:13 box:backupupload v8 heap : used 30215776 total: 41152512 max: 1526909922
Dec 24 03:53:21 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 27691M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:53:31 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 27739M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:53:41 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 27766M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:53:43 box:shell backup-snapshot/app_d0e0fa7c-e358-4d93-869b-e227feec349f (stdout): 2020-12-24T03:53:43.897Z box:backupupload process: rss: 50860032 heapTotal: 40103936 heapUsed: 29142336 external: 3502970
Dec 24 03:53:43 box:backupupload v8 heap : used 29142472 total: 40103936 max: 1526909922
Dec 24 03:53:51 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 27797M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:54:01 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 27843M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:54:11 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 27894M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:54:13 box:shell backup-snapshot/app_d0e0fa7c-e358-4d93-869b-e227feec349f (stdout): 2020-12-24T03:54:13.896Z box:backupupload process: rss: 59416576 heapTotal: 40103936 heapUsed: 28492712 external: 455034
Dec 24 03:54:13 box:shell backup-snapshot/app_d0e0fa7c-e358-4d93-869b-e227feec349f (stdout): 2020-12-24T03:54:13.897Z box:backupupload v8 heap : used 28492848 total: 40103936 max: 1526909922
Dec 24 03:54:21 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 27944M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:54:31 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 27991M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:54:41 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 28022M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:54:43 box:shell backup-snapshot/app_d0e0fa7c-e358-4d93-869b-e227feec349f (stdout): 2020-12-24T03:54:43.913Z box:backupupload process: rss: 35647488 heapTotal: 40103936 heapUsed: 28482184 external: 2145146
Dec 24 03:54:43 box:shell backup-snapshot/app_d0e0fa7c-e358-4d93-869b-e227feec349f (stdout): 2020-12-24T03:54:43.923Z box:backupupload v8 heap : used 28482320 total: 40103936 max: 1526909922
Dec 24 03:54:52 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 28058M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:55:02 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 28103M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:55:12 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 28158M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:55:13 box:shell backup-snapshot/app_d0e0fa7c-e358-4d93-869b-e227feec349f (stdout): 2020-12-24T03:55:13.902Z box:backupupload process: rss: 39378944 heapTotal: 41152512 heapUsed: 29247864 external: 12602234
Dec 24 03:55:13 box:backupupload v8 heap : used 29248000 total: 41152512 max: 1526909922
Dec 24 03:55:22 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 28211M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:55:32 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 28259M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:55:42 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 28288M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:55:43 box:shell backup-snapshot/app_d0e0fa7c-e358-4d93-869b-e227feec349f (stdout): 2020-12-24T03:55:43.902Z box:backupupload process: rss: 37691392 heapTotal: 40103936 heapUsed: 29441000 external: 16565114
Dec 24 03:55:43 box:backupupload v8 heap : used 29441136 total: 40103936 max: 1526909922
Dec 24 03:55:52 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 28322M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:55:58 box:tasks 3286: {"percent":72.4285714285714,"message":"Uploading backup 28344M@4MBps (office.uniteddiversity.coop)"}
Dec 24 03:56:13 box:shell backup-snapshot/app_d0e0fa7c-e358-4d93-869b-e227feec349f (stdout): 2020-12-24T03:56:13.902Z box:backupupload process: rss: 51838976 heapTotal: 43249664 heapUsed: 31012632 external: 1346066
Dec 24 03:56:13 box:backupupload v8 heap : used 31012768 total: 43249664 max: 1526909922
Dec 24 03:56:43 box:shell backup-snapshot/app_d0e0fa7c-e358-4d93-869b-e227feec349f (stdout): 2020-12-24T03:56:43.902Z box:backupupload process: rss: 52428800 heapTotal: 43249664 heapUsed: 31273968 external: 2607346
Dec 24 03:56:43 box:backupupload v8 heap : used 31274104 total: 43249664 max: 1526909922
Dec 24 03:57:03 box:shell backup-snapshot/app_d0e0fa7c-e358-4d93-869b-e227feec349f (stdout): 2020-12-24T03:57:03.845Z box:storage/filesystem [/mnt/backup/snapshot/app_d0e0fa7c-e358-4d93-869b-e227feec349f.tar.gz] upload: out stream error. { [Error: EBADF: bad file descriptor, close] errno: -9, code: 'EBADF', syscall: 'close' }
Dec 24 03:57:13 box:shell backup-snapshot/app_d0e0fa7c-e358-4d93-869b-e227feec349f (stdout): 2020-12-24T03:57:13.904Z box:backupupload process: rss: 53137408 heapTotal: 43249664 heapUsed: 31447408 external: 3270754
Dec 24 03:57:13 box:shell backup-snapshot/app_d0e0fa7c-e358-4d93-869b-e227feec349f (stdout): 2020-12-24T03:57:13.904Z box:backupupload v8 heap : used 31447544 total: 43249664 max: 1526909922
Dec 24 03:57:19 box:shell backup-snapshot/app_d0e0fa7c-e358-4d93-869b-e227feec349f (stdout): 2020-12-24T03:57:19.109Z box:backupupload upload completed. error: { BoxError: Unknown system error -128: Unknown system error -128, mkdir
at /home/yellowtent/box/src/storage/filesystem.js:93:36
at FSReqWrap.args [as oncomplete] (fs.js:140:20)
name: 'BoxError',
reason: 'External Error',
details: {},
message:
'Unknown system error -128: Unknown system error -128, mkdir' }
Dec 24 03:57:19 box:backups runBackupUpload: result - {"result":"Unknown system error -128: Unknown system error -128, mkdir"}
Dec 24 03:57:19 box:shell backup-snapshot/app_d0e0fa7c-e358-4d93-869b-e227feec349f code: 50, signal: null
Dec 24 03:57:19 box:backups office.uniteddiversity.coop Unable to backup { BoxError: Unknown system error -128: Unknown system error -128, mkdir
at /home/yellowtent/box/src/backups.js:874:29
at f (/home/yellowtent/box/node_modules/once/once.js:25:25)
at ChildProcess.<anonymous> (/home/yellowtent/box/src/shell.js:69:9)
at ChildProcess.emit (events.js:198:13)
at Process.ChildProcess._handle.onexit (internal/child_process.js:248:12)
name: 'BoxError',
reason: 'External Error',
details: {},
message:
'Unknown system error -128: Unknown system error -128, mkdir' }
Dec 24 03:57:19 box:taskworker Task took 7038.095 seconds
Dec 24 03:57:19 box:tasks setCompleted - 3286: {"result":null,"error":{"stack":"BoxError: Unknown system error -128: Unknown system error -128, mkdir\n at /home/yellowtent/box/src/backups.js:874:29\n at f (/home/yellowtent/box/node_modules/once/once.js:25:25)\n at ChildProcess.<anonymous> (/home/yellowtent/box/src/shell.js:69:9)\n at ChildProcess.emit (events.js:198:13)\n at Process.ChildProcess._handle.onexit (internal/child_process.js:248:12)","name":"BoxError","reason":"External Error","details":{},"message":"Unknown system error -128: Unknown system error -128, mkdir"}}
Dec 24 03:57:19 box:tasks 3286: {"percent":100,"result":null,"error":{"stack":"BoxError: Unknown system error -128: Unknown system error -128, mkdir\n at /home/yellowtent/box/src/backups.js:874:29\n at f (/home/yellowtent/box/node_modules/once/once.js:25:25)\n at ChildProcess.<anonymous> (/home/yellowtent/box/src/shell.js:69:9)\n at ChildProcess.emit (events.js:198:13)\n at Process.ChildProcess._handle.onexit (internal/child_process.js:248:12)","name":"BoxError","reason":"External Error","details":{},"message":"Unknown system error -128: Unknown system error -128, mkdir"}}

I figured I'd start by just trying to run the backup again, but it fails immediately and I get this:

Command failed with exit code 1 (EPERM): df -kPT /mnt/backup

Which I guess means the backup mount isn't mounted.... so I rebooted to see if that would fix that...which it did... so now seeing if a backup will now complete...

jdaviescoates

Backing up post-reboot worked fine. So my guess is that my Hetzner Storage Box had a wobble and somehow became unmounted mid backup.

robi

we need better retries for mounts and DB connections during long running processes such as backups.

p44

@jdaviescoates I had a similar problem. I don't know if @nebulon reached Hetzner provider to ask more info's about long-time mounting of Box service.

iqweb

same here on a Hetzner storage box 2 days back - couldn't manually remount either. Had to reboot & then remounted automatically as per /etc/fstab.

girish

@jdaviescoates Did this get sorted out?

jdaviescoates

@girish yes:

@jdaviescoates said in Backup failing:

Backing up post-reboot worked fine. So my guess is that my Hetzner Storage Box had a wobble and somehow became unmounted mid backup.

Sounds like others have been experiencing similar too, so I'm guessing a (hopefully temporary) issue with Hetzner storage boxes.

Although like @robi said it'd be cool if there was some way Cloudron backups could try to survive such wobbles.

girish

@jdaviescoates Yes, at some point we want to make it possible to add mounts easily. When we do that, we can attempt to re-mount automatically, I guess.

robi

@girish not sure this is the right context..

this is about existing mounts and their resilience to disconnects.

monitoring mounts for health
allowing for self-healing if it exists from the protocol
if not, try harder, remount command for example
if still not, try unmount, then remount
if still not, notify to reboot

p44

@robi right suggestions.

@girish I had this problem again: all backup folder this morning where unmounted...

iqweb

@p44 said in Backup failing:

@robi right suggestions.

@girish I had this problem again: all backup folder this morning where unmounted...

I've had the same thing again too

girish

@iqweb Are you also using CIFS/NFS?

p44

@iqweb Still on Hetzner storage?

iqweb

@girish said in Backup failing:

@iqweb Are you also using CIFS/NFS?

Yes - storage provider: CIFS Mount

@p44 said in Backup failing:

@iqweb Still on Hetzner storage?

Yes - Hetzner storage box

& again - I had to reboot to be able to remount.

p44

@iqweb Maybe Hetzner sometimes reboot Box instance? From my side is about one week CIFS mount is stable...

nebulon

I also have to remount my cifs share about once a month. In my case I thought it was related to my residential home internet connection. Either way I think we have to handle such mount points better and maybe even attempt a remount automatically.

p44

@nebulon Good idea to add a health-check to keep alive mounting

girish

@nebulon Does cifs mounting have some retry flags? (i.e the fstab options)

nebulon

@girish not that I have found and https://linux.die.net/man/8/mount.cifs does not mention anything.

Apparently systemd has some automounting feature https://www.freedesktop.org/software/systemd/man/systemd.automount.html which mounts the drive once the mountpoint is accessed by a process! Can't tell if it would reconnect such a mount though.

girish

@nebulon Maybe https://askubuntu.com/questions/1210867/remount-cifs-on-network-reconnect ? (just expands on your link)

Cloudron makes it easy to run web apps like WordPress, Nextcloud, GitLab on your server. Find out more or install now.

Cloudron Forum

Backup failing (flaky CIFS mount)