Hi there James,
yes it is ... again today.
I asked AI for an idea about the potential reason:
Summary of Backup Issue
A backup was created and uploaded successfully to an IONOS S3 bucket. The archive size was about 46 GB containing 13,069 files, and the upload completed without errors. The corresponding .backupinfo integrity file was also uploaded successfully.
Immediately after the upload, the system attempted to rotate the backup by copying the snapshot object to its final timestamped location using an S3 multipart copy operation.
During this step the copy process failed with:
NoSuchKey: UnknownError
The application reported this as:
Old backup not found: snapshot/app_<uuid>.tar.gz.enc
This is inconsistent with the previous log entry indicating that the upload had just finished successfully.
Observed behavior
- Upload of the snapshot completed successfully.
- Integrity metadata upload succeeded.
- Multipart copy started.
- The copy operation was aborted and S3 returned
NoSuchKey. - The backup task was marked as failed, even though the snapshot object appears to have been uploaded.
Likely causes
- The system attempts to copy the object immediately after upload and the object is temporarily not readable (possible S3 consistency timing issue).
- A mismatch between the key/bucket/endpoint used during upload and the one used during the copy operation.
- A bug in the multipart copy implementation used by the backup system.
In summary, the backup upload itself succeeded, but the post-upload rotation (copy) step failed because the source object could not be found by the S3 copy operation.
Here is the log again. Please have a look at the time stamps. Also strange is the percentage for the copy process. Always the same...
Mar 08 05:27:51 box:storage/s3 Upload progress: {"loaded":46025049716,"part":343,"Key":"snapshot/app_<uuid>.tar.gz.enc","Bucket":"<bucket>"}
Mar 08 05:48:32 box:storage/s3 Upload finished. {"Location":"s3.eu-central-3.ionoscloud.com/<bucket>/snapshot/app_<uuid>.tar.gz.enc","Bucket":"<bucket>","Key":"snapshot/app_<uuid>.tar.gz.enc","ETag":"\"\"","$metadata":{"httpStatusCode":200,"requestId":"tx0000017c8a2550b10c59d-0069acffa0-767801809-eu-central-3","attempts":3,"totalRetryDelay":40000}}
Mar 08 05:48:32 box:backuptask upload: path snapshot/app_<uuid>.tar.gz.enc site <uuid> uploaded: {"fileCount":13069,"size":46025049716,"transferred":46025049716}
Mar 08 05:48:32 box:tasks updating task 9150 with: {"percent":76.36231884057979,"message":"Uploading integrity information to snapshot/app_<uuid>.tar.gz.enc.backupinfo (<app-domain>)"}
Mar 08 05:48:32 box:storage/s3 Upload progress: {"loaded":146,"total":146,"part":1,"Key":"snapshot/app_<uuid>.tar.gz.enc.backupinfo","Bucket":"<bucket>"}
Mar 08 05:48:32 box:storage/s3 Upload finished. {"ETag":"\"c3b40730b7df7334109478d49c4fc7c6\"","$metadata":{"httpStatusCode":200,"requestId":"tx0000009b25a1e91abf3e9-0069acffa0-767802089-eu-central-3","attempts":1,"totalRetryDelay":0},"Bucket":"<bucket>","Key":"snapshot/app_<uuid>.tar.gz.enc.backupinfo","Location":"https://<bucket>.s3.eu-central-3.ionoscloud.com/snapshot/app_<uuid>.tar.gz.enc.backupinfo"}
Mar 08 05:48:32 box:backupupload upload completed. error: null
Mar 08 05:48:32 box:backuptask runBackupUpload: result - {"result":{"stats":{"fileCount":13069,"size":46025049716,"transferred":46025049716},"integrity":{"signature":"c2a556116f2b4a143f8a22796ea4d64751a9e71677c16a2e9c1dcef80e218ed7bcd65fa797fc480b1f69437e14242f35c78e5cc96ad77b1179b8b570b98cbd01"}}}
Mar 08 05:48:32 box:backuptask uploadAppSnapshot: <app-domain> uploaded to snapshot/app_<uuid>.tar.gz.enc. 4338.546 seconds
Mar 08 05:48:32 box:backuptask backupAppWithTag: rotating <app-domain> snapshot of <uuid> to path 2026-03-08-030001-701/app_<app-domain>_v1.13.0.tar.gz.enc
Mar 08 05:48:32 box:tasks updating task 9150 with: {"percent":76.36231884057979,"message":"Copying (multipart) snapshot/app_<uuid>.tar.gz.enc"}
Mar 08 05:48:32 box:tasks updating task 9150 with: {"percent":76.36231884057979,"message":"Copying part 1 - <bucket>/snapshot/app_<uuid>.tar.gz.enc bytes=0-1073741823"}
Mar 08 05:48:32 box:tasks updating task 9150 with: {"percent":76.36231884057979,"message":"Copying part 2 - <bucket>/snapshot/app_<uuid>.tar.gz.enc bytes=1073741824-2147483647"}
Mar 08 05:48:32 box:tasks updating task 9150 with: {"percent":76.36231884057979,"message":"Copying part 3 - <bucket>/snapshot/app_<uuid>.tar.gz.enc bytes=2147483648-3221225471"}
Mar 08 05:48:32 box:tasks updating task 9150 with: {"percent":76.36231884057979,"message":"Aborting multipart copy of snapshot/app_<uuid>.tar.gz.enc"}
Mar 08 05:48:32 box:storage/s3 copy: s3 copy error when copying snapshot/app_<uuid>.tar.gz.enc: NoSuchKey: UnknownError
Mar 08 05:48:32 box:backuptask copy: copy to 2026-03-08-030001-701/app_<app-domain>_v1.13.0.tar.gz.enc errored. error: Old backup not found: snapshot/app_<uuid>.tar.gz.enc
Mar 08 05:48:32 box:backuptask fullBackup: app <app-domain> backup finished. Took 4338.955 seconds
Mar 08 05:48:32 box:locks write: current locks: {"full_backup_task_<uuid>":null}
Mar 08 05:48:32 box:locks release: app_backup_<uuid>
Mar 08 05:48:32 box:tasks setCompleted - 9150: {"result":null,"error":{"message":"Old backup not found: snapshot/app_<uuid>.tar.gz.enc","reason":"Not found"},"percent":100}
Mar 08 05:48:32 box:tasks updating task 9150 with: {"completed":true,"result":null,"error":{"message":"Old backup not found: snapshot/app_<uuid>.tar.gz.enc","reason":"Not found"},"percent":100}
Mar 08 05:48:32 box:taskworker Task took 6510.865 seconds
Mar 08 05:48:32 BoxError: Old backup not found: snapshot/app_<uuid>.tar.gz.enc
Mar 08 05:48:32 at throwError (file:///home/yellowtent/box/src/storage/s3.js:540:49)
Mar 08 05:48:32 at copyInternal (file:///home/yellowtent/box/src/storage/s3.js:607:16)
Mar 08 05:48:32 at process.processTicksAndRejections (node:internal/process/task_queues:103:5)
Mar 08 05:48:32 at async Object.copy (file:///home/yellowtent/box/src/storage/s3.js:641:12)
Mar 08 05:48:32 at async Object.copy (file:///home/yellowtent/box/src/backupformat/tgz.js:284:5)
Mar 08 05:48:32 Exiting with code 0
Based on the S3 storage timestamps the file was already there at 05:48 - also in the correct path:
