[FIXED] Nextcloud AIO Backup on goofys mount: extended stat (xattrs): [Errno 5] I/O error: '<FD 7>'

I’m attempting to run a backup on a goofys mounted directory.

Getting the following error (note that the first character of each line is not logged):

ud_aio_volumes/nextcloud_aio_nextcloud_data: extended stat (xattrs): [Errno 5] I/O error: '<FD 7>'

How can I set up the mount directory permissions to properly create a backup?

As I/O error is (generally) more than a permissions problem.

Are you trying to use the goofys mount as a target for the Borg backup?

Or are you just to use the integrated Borg backup functionality to try to backup your goofys mounted data to some other destination?

If the former:

Another point I did not mention…The next cloud data directory is also mounted using goofys (/mnt/nextcloud-data). The backup is failing on nextcloud_aio_nextcloud_data. My suspicion is that borg is having issues with the mount on nextcloud_aio_nextcloud_data.

I’m going through the backup script to reproduce the issue from the command line.

Or are you just to use the integrated Borg backup functionality to try to backup your goofys mounted data to some other destination?

The target directory is also a goofys mount (/mnt/nextcloud-backup). However, it seems like files are being written to the mounted directory.

I found some code which seems related, by searching for “extended stat (xattrs)”:

Following the error formatting code:

So extended stat (xattrs) comes from with backup_io("extended stat (xattrs)"): & [Errno 5] I/O error: '<FD 7>' is the os error that is thrown in xattr.get_all(fd or path, follow_symlinks=False).

I’ll keep on diving into the issue…

Continuing…

I inspected getxattr, which comes from:

Running:

docker run --rm -it --entrypoint bash nextcloud/aio-borgbackup
2fd7f63de414:/# python
Python 3.11.4 (main, Jun  9 2023, 02:29:05) [GCC 12.2.1 20220924] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import sys
>>> sys.platform.startswith("linux")
True

Which indicates that is_linux is True.

Which leads to:

follow_symlinks is False, so one of the following are called:

return c_fgetxattr(path, name, <char *> buf, size)
return c_lgetxattr(path, name, <char *> buf, size)

Given that the error contains <FD 7> as in File Descriptor 7, I suspect that if isinstance(path, int): is True, so return c_fgetxattr(path, name, <char *> buf, size) would be throwing the error.

Which leads to:

errno 5
EIO 5 Input/output error

Continuing…I added --debug_fuse --debug_s3 -f flags goofys, which debug fuse, s3, & runs goofys in the foreground. Running the following in separate sessions:

For the data mount:

sudo goofys --endpoint=usc1.contabostorage.com -o allow_other --file-mode=0666 --dir-mode=0777 --uid=33 --gid=0 --debug_fuse --debug_s3 -f foresight-nextcloud-data /mnt/foresight-nextcloud-data

For the backup mount:

sudo goofys --endpoint=usc1.contabostorage.com -o allow_other --file-mode=0755 --dir-mode=0644 --uid=0 --gid=0 --debug_fuse --debug_s3 -f foresight-nextcloud-backup /mnt/foresight-nextcloud-backup

The data mount had the following logs at the time of the error:

2023/07/06 05:55:43.876059 fuse.DEBUG Op 0x0000002a        connection.go:408] <- GetInodeAttributes (inode 1)
2023/07/06 05:55:43.876339 fuse.DEBUG GetAttributes 1  []
2023/07/06 05:55:43.876442 fuse.DEBUG Op 0x0000002a        connection.go:491] -> OK ()
2023/07/06 05:55:43.876890 fuse.DEBUG Op 0x0000002c        connection.go:408] <- OpenDir (inode 1)
2023/07/06 05:55:43.877006 fuse.DEBUG OpenDir 1  []
2023/07/06 05:55:43.877068 fuse.DEBUG Op 0x0000002c        connection.go:491] -> OK ()
2023/07/06 05:55:43.877296 fuse.DEBUG Op 0x0000002e        connection.go:408] <- LookUpInode (parent 1, name "CACHEDIR.TAG")
2023/07/06 05:55:43.877505 fuse.DEBUG Inode.LookUp 1  [CACHEDIR.TAG]
2023/07/06 05:55:43.878151 s3.DEBUG DEBUG: Request s3/HeadObject Details:
---[ REQUEST POST-SIGN ]-----------------------------
HEAD /foresight-nextcloud-data/CACHEDIR.TAG HTTP/1.1
Host: usc1.contabostorage.com
User-Agent: aws-sdk-go/1.17.13 (go1.13.1; linux; amd64)
Authorization: AWS4-HMAC-SHA256 Credential=6d9a0f873e6d07387aad8ef290238685/20230706/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=2f318c3f5cfb6b028127f7216be9687893278537c0fa91cb846b7c3b40da42e9
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20230706T035543Z


-----------------------------------------------------
2023/07/06 05:55:43.879350 s3.DEBUG DEBUG: Request s3/ListObjects Details:
---[ REQUEST POST-SIGN ]-----------------------------
GET /foresight-nextcloud-data?delimiter=%2F&max-keys=1&prefix=CACHEDIR.TAG%2F HTTP/1.1
Host: usc1.contabostorage.com
User-Agent: aws-sdk-go/1.17.13 (go1.13.1; linux; amd64)
Accept-Encoding: identity
Authorization: AWS4-HMAC-SHA256 Credential=6d9a0f873e6d07387aad8ef290238685/20230706/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=f2e07b9cd309b84ae659acb48974d8f935bdcc468970814fdf07c80529485b6c
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20230706T035543Z


-----------------------------------------------------
2023/07/06 05:55:43.879424 s3.DEBUG DEBUG: Request s3/HeadObject Details:
---[ REQUEST POST-SIGN ]-----------------------------
HEAD /foresight-nextcloud-data/CACHEDIR.TAG/ HTTP/1.1
Host: usc1.contabostorage.com
User-Agent: aws-sdk-go/1.17.13 (go1.13.1; linux; amd64)
Authorization: AWS4-HMAC-SHA256 Credential=6d9a0f873e6d07387aad8ef290238685/20230706/us-east-1/s3/aws4_request, SignedHeaders=host;x-amz-content-sha256;x-amz-date, Signature=027338bd138ef67c76059cf39d621e18470a0dc2b6f8d42d87c26c7c947c79e9
X-Amz-Content-Sha256: e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855
X-Amz-Date: 20230706T035543Z


-----------------------------------------------------
2023/07/06 05:55:43.894018 s3.DEBUG DEBUG: Response s3/ListObjects Details:
---[ RESPONSE ]--------------------------------------
HTTP/1.1 200 OK
Transfer-Encoding: chunked
Access-Control-Allow-Origin: *
Access-Control-Expose-Headers: *
Content-Type: application/xml
Date: Thu, 06 Jul 2023 03:55:43 GMT
Ratelimit-Limit: 250
Ratelimit-Remaining: 241
Ratelimit-Reset: 1
Strict-Transport-Security: max-age=16000000; includeSubDomains; preload;
Vary: Origin
X-Amz-Request-Id: tx000005ec896de8b312148-0064a63b3f-2bbe8e-default
X-Ratelimit-Limit-Second: 250
X-Ratelimit-Remaining-Second: 241


-----------------------------------------------------
2023/07/06 05:55:43.894099 s3.DEBUG &{[] [] <nil> false }
2023/07/06 05:55:43.894972 s3.DEBUG DEBUG: Response s3/HeadObject Details:
---[ RESPONSE ]--------------------------------------
HTTP/1.1 404 Not Found
Content-Length: 235
Accept-Ranges: bytes
Access-Control-Allow-Origin: *
Access-Control-Expose-Headers: *
Content-Type: application/xml
Date: Thu, 06 Jul 2023 03:55:43 GMT
Ratelimit-Limit: 250
Ratelimit-Remaining: 242
Ratelimit-Reset: 1
Strict-Transport-Security: max-age=16000000; includeSubDomains; preload;
Vary: Origin
X-Amz-Request-Id: tx0000034be3e6818edfb75-0064a63b3f-2bbe2f-default
X-Ratelimit-Limit-Second: 250
X-Ratelimit-Remaining-Second: 242


-----------------------------------------------------
2023/07/06 05:55:43.895031 s3.DEBUG DEBUG: Validate Response s3/HeadObject failed, not retrying, error NotFound: Not Found
        status code: 404, request id: tx0000034be3e6818edfb75-0064a63b3f-2bbe2f-default, host id:
2023/07/06 05:55:43.895078 s3.DEBUG HEAD CACHEDIR.TAG = no such file or directory
2023/07/06 05:55:43.895525 s3.DEBUG DEBUG: Response s3/HeadObject Details:
---[ RESPONSE ]--------------------------------------
HTTP/1.1 404 Not Found
Content-Length: 235
Accept-Ranges: bytes
Access-Control-Allow-Origin: *
Access-Control-Expose-Headers: *
Content-Type: application/xml
Date: Thu, 06 Jul 2023 03:55:43 GMT
Ratelimit-Limit: 250
Ratelimit-Remaining: 240
Ratelimit-Reset: 1
Strict-Transport-Security: max-age=16000000; includeSubDomains; preload;
Vary: Origin
X-Amz-Request-Id: tx000005e0510eac5208bf7-0064a63b3f-2bbe2f-default
X-Ratelimit-Limit-Second: 250
X-Ratelimit-Remaining-Second: 240


-----------------------------------------------------
2023/07/06 05:55:43.895564 s3.DEBUG DEBUG: Validate Response s3/HeadObject failed, not retrying, error NotFound: Not Found
        status code: 404, request id: tx000005e0510eac5208bf7-0064a63b3f-2bbe2f-default, host id:
2023/07/06 05:55:43.895580 s3.DEBUG HEAD CACHEDIR.TAG/ = no such file or directory
2023/07/06 05:55:43.895598 fuse.DEBUG <-- LookUpInode 1 CACHEDIR.TAG no such file or directory
2023/07/06 05:55:43.895632 fuse.DEBUG Op 0x0000002e        connection.go:493] -> Error: "no such file or directory"
2023/07/06 05:55:43.896036 fuse.DEBUG Op 0x00000030        connection.go:408] <- OpenDir (inode 1)
2023/07/06 05:55:43.896104 fuse.DEBUG OpenDir 1  []
2023/07/06 05:55:43.896145 fuse.DEBUG Op 0x00000030        connection.go:491] -> OK ()
2023/07/06 05:55:43.896217 fuse.DEBUG Op 0x00000032        connection.go:408] <- unknown (inode 1, opcode 39)
2023/07/06 05:55:43.896271 fuse.DEBUG Op 0x00000032        connection.go:493] -> Error: "function not implemented"
2023/07/06 05:55:43.896328 fuse.DEBUG Op 0x00000034        connection.go:408] <- ReleaseDirHandle
2023/07/06 05:55:43.896402 fuse.DEBUG ReleaseDirHandle
2023/07/06 05:55:43.896470 fuse.DEBUG Op 0x00000034        connection.go:491] -> OK ()
2023/07/06 05:55:43.896512 fuse.DEBUG Op 0x00000036        connection.go:408] <- ListXattr (inode 1)
2023/07/06 05:55:43.896556 fuse.DEBUG ListXattr 1  []
2023/07/06 05:55:43.896653 s3.DEBUG DEBUG: Validate Request s3/HeadObject failed, not retrying, error InvalidParameter: 1 validation error(s) found.
- minimum field size of 1, HeadObjectInput.Key.

2023/07/06 05:55:43.896702 s3.DEBUG DEBUG: Build Request s3/HeadObject failed, not retrying, error InvalidParameter: 1 validation error(s) found.
- minimum field size of 1, HeadObjectInput.Key.

2023/07/06 05:55:43.896739 s3.DEBUG DEBUG: Sign Request s3/HeadObject failed, not retrying, error InvalidParameter: 1 validation error(s) found.
- minimum field size of 1, HeadObjectInput.Key.

2023/07/06 05:55:43.896761 s3.ERROR code=InvalidParameter msg=1 validation error(s) found., err=InvalidParameter: 1 validation error(s) found.
caused by: ParamMinLenError: minimum field size of 1, HeadObjectInput.Key.

2023/07/06 05:55:43.896780 s3.ERROR code=InvalidParameter msg=1 validation error(s) found., err=InvalidParameter: 1 validation error(s) found.
caused by: ParamMinLenError: minimum field size of 1, HeadObjectInput.Key.

2023/07/06 05:55:43.896806 fuse.DEBUG Op 0x00000036        connection.go:493] -> Error: "InvalidParameter: 1 validation error(s) found.\n- minimum field size of 1, HeadObjectInput.Key.\n"
2023/07/06 05:55:43.896832 fuse.ERROR *fuseops.ListXattrOp error: InvalidParameter: 1 validation error(s) found.
2023/07/06 05:55:43.896845 fuse.ERROR - minimum field size of 1, HeadObjectInput.Key.
2023/07/06 05:55:43.897283 fuse.DEBUG Op 0x00000038        connection.go:408] <- ReleaseDirHandle
2023/07/06 05:55:43.897340 fuse.DEBUG ReleaseDirHandle
2023/07/06 05:55:43.897372 fuse.DEBUG Op 0x00000038        connection.go:491] -> OK ()

And the backup had the logs around the time of the error:

2023/07/06 05:55:43.868851 fuse.DEBUG GetXattr 41 borg/data/0/26 [security.capability]
2023/07/06 05:55:43.868878 fuse.DEBUG Op 0x0001056c        connection.go:493] -> Error: "no data available"
2023/07/06 05:55:43.868939 fuse.DEBUG Op 0x0001056e        connection.go:408] <- WriteFile (inode 41, handle 29, offset 317838198, 3210 bytes)
2023/07/06 05:55:43.869000 fuse.DEBUG WriteFile 41 borg/data/0/26 [317838198 3210]
2023/07/06 05:55:43.869036 fuse.DEBUG Op 0x0001056e        connection.go:491] -> OK ()
2023/07/06 05:55:43.869139 fuse.DEBUG Op 0x00010570        connection.go:408] <- WriteFile (inode 41, handle 29, offset 317841408, 789 bytes)
2023/07/06 05:55:43.869244 fuse.DEBUG WriteFile 41 borg/data/0/26 [317841408 789]
2023/07/06 05:55:43.869275 fuse.DEBUG Op 0x00010570        connection.go:491] -> OK ()
2023/07/06 05:55:43.902828 fuse.DEBUG Op 0x00010572        connection.go:408] <- GetXattr (inode 41, name "security.capability", name security.capability)
2023/07/06 05:55:43.902939 fuse.DEBUG GetXattr 41 borg/data/0/26 [security.capability]
2023/07/06 05:55:43.903008 fuse.DEBUG Op 0x00010572        connection.go:493] -> Error: "no data available"
2023/07/06 05:55:43.903150 fuse.DEBUG Op 0x00010574        connection.go:408] <- WriteFile (inode 41, handle 29, offset 317842197, 3307 bytes)
2023/07/06 05:55:43.903244 fuse.DEBUG WriteFile 41 borg/data/0/26 [317842197 3307]
2023/07/06 05:55:43.903287 fuse.DEBUG Op 0x00010574        connection.go:491] -> OK ()
2023/07/06 05:55:43.903408 fuse.DEBUG Op 0x00010576        connection.go:408] <- WriteFile (inode 41, handle 29, offset 317845504, 264 bytes)
2023/07/06 05:55:43.903479 fuse.DEBUG WriteFile 41 borg/data/0/26 [317845504 264]
2023/07/06 05:55:43.903527 fuse.DEBUG Op 0x00010576        connection.go:491] -> OK ()
2023/07/06 05:55:43.904888 fuse.DEBUG Op 0x00010578        connection.go:408] <- GetXattr (inode 41, name "security.capability", name security.capability)

Notice that the backup logs has a gap during the time of the logged data errors.

This seems to confirm that the problem lies in the data mount.

Focusing on the data mount S3 errors:

2023/07/06 05:55:43.896653 s3.DEBUG DEBUG: Validate Request s3/HeadObject failed, not retrying, error InvalidParameter: 1 validation error(s) found.
- minimum field size of 1, HeadObjectInput.Key.

2023/07/06 05:55:43.896702 s3.DEBUG DEBUG: Build Request s3/HeadObject failed, not retrying, error InvalidParameter: 1 validation error(s) found.
- minimum field size of 1, HeadObjectInput.Key.

2023/07/06 05:55:43.896739 s3.DEBUG DEBUG: Sign Request s3/HeadObject failed, not retrying, error InvalidParameter: 1 validation error(s) found.
- minimum field size of 1, HeadObjectInput.Key.

2023/07/06 05:55:43.896761 s3.ERROR code=InvalidParameter msg=1 validation error(s) found., err=InvalidParameter: 1 validation error(s) found.
caused by: ParamMinLenError: minimum field size of 1, HeadObjectInput.Key.

2023/07/06 05:55:43.896780 s3.ERROR code=InvalidParameter msg=1 validation error(s) found., err=InvalidParameter: 1 validation error(s) found.
caused by: ParamMinLenError: minimum field size of 1, HeadObjectInput.Key.

2023/07/06 05:55:43.896806 fuse.DEBUG Op 0x00000036        connection.go:493] -> Error: "InvalidParameter: 1 validation error(s) found.\n- minimum field size of 1, HeadObjectInput.Key.\n"

Will continue with debugging…

I found an issue with the fuse error at:

Looks like development is still happening though it is slow. May have to use the slower performing s3fs-fuse project in the mean time, or apply a patch…

1 Like

I’m sure of your use case, but Nextcloud does support S3 natively both as Primary Storage or as External Storage w/o any need for FUSE.

I ended up applying the patch to fix goofys. I’m maintaining the btakita/goofys prod branch to stay up to date with the kahing/goofys master branch with the patch applied. I can confirm that the backup now works.

I want to have the primary storage expandable using Object Storage. I’m hesitant to use Nextcloud’s application to manage the Object Storage because the files are stored as a BLOB & not readable from the file system. I’m new to Nextcloud administration & have already borked a backup & got locked out of the DB using Nextcloud AIO; so I want to be able to have the fallback of at least being able to retrieve the data files.

Another reason is a report that S3FS is more scalable than the Nextcloud managed Object Store backend. I’m also concerned about the migration path from Nextcloud’s Object Store to a File System based implementation such as NFS Mount or S3 Fuse mount in the future.

Note that the currently unreleased 0.25.0 release should have the fix for this issue. So if you come across this, please check to see if v0.25.0 or greater has been released & use that if it is. Otherwise, use the branch above.