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…