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)