Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection

glaurent · May 2, 2018, 2:04pm

Hi,

Seems other people also faced this issue, but there is no clear answer / solution for now.

After upgrading to v2.0.3.5-2.0.3.5_canary_2018-04-13, few of my backups received warning with:

Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection

I tried to Repair DB, and Rebuild DB, but the result was even worst, as backup failed after.
_See Problem with backup after canceling it - #7 by glaurent

As one of my backup set is small (4GB), I choose to delete all the files on the remote, and restart the backup from scratch … but the warning still occurs.

I will try to revert to a previous version, like v2.0.2.21-2.0.2.21_canary_2018-03-06.

But what happens with the latest Canary ?

Logs from a backup from scratch (well, logs from the 2nd backup in fact, but had the warning on the 1st run too).

DeletedFiles: 2
DeletedFolders: 0
ModifiedFiles: 34
ExaminedFiles: 40272
OpenedFiles: 37
AddedFiles: 3
SizeOfModifiedFiles: 50486821
SizeOfAddedFiles: 40858907
SizeOfExaminedFiles: 5192085871
SizeOfOpenedFiles: 91541731
NotProcessedFiles: 0
AddedFolders: 0
TooLargeFiles: 0
FilesWithError: 0
ModifiedFolders: 0
ModifiedSymlinks: 0
AddedSymlinks: 0
DeletedSymlinks: 0
PartialBackup: False
Dryrun: False
MainOperation: Backup
CompactResults:
    DeletedFileCount: 0
    DownloadedFileCount: 0
    UploadedFileCount: 0
    DeletedFileSize: 0
    DownloadedFileSize: 0
    UploadedFileSize: 0
    Dryrun: False
    MainOperation: Compact
    ParsedResult: Error
    EndTime: 02/05/2018 08:26:37 (1525263997)
    BeginTime: 02/05/2018 08:26:36 (1525263996)
    Duration: 00:00:00.2971280
    Messages: [
        2018-05-02 08:25:59 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
        2018-05-02 08:25:59 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2018-05-02 08:26:00 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (146 bytes),
        2018-05-02 08:26:30 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bc03f1b04c9aa4632a89b6570c422c37a.dblock.zip.aes (48,19 MB),
        2018-05-02 08:26:35 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bc03f1b04c9aa4632a89b6570c422c37a.dblock.zip.aes (48,19 MB),
...
    ]
    Warnings: []
    Errors: [
        2018-05-02 08:27:17 -04 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-20180502T032710Z.dlist.zip.aes,
        2018-05-02 08:27:58 -04 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-i623316c958ec4cdaaff6cbc5cebf44cc.dindex.zip.aes,
        2018-05-02 08:28:38 -04 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-bb2acf03d9ee349dab18d764f51cba802.dblock.zip.aes
    ]
    BackendStatistics:
        RemoteCalls: 21
        BytesUploaded: 52996759
        BytesDownloaded: 0
        FilesUploaded: 3
        FilesDownloaded: 0
        FilesDeleted: 1
        FoldersCreated: 0
        RetryAttempts: 12
        UnknownFileSize: 0
        UnknownFileCount: 0
        KnownFileCount: 148
        KnownFileSize: 3754134900
        LastBackupDate: 02/05/2018 08:25:59 (1525263959)
        BackupListCount: 2
        TotalQuotaSpace: 0
        FreeQuotaSpace: 0
        AssignedQuotaSpace: -1
        ReportedQuotaError: False
        ReportedQuotaWarning: False
        ParsedResult: Error
        Messages: [
            2018-05-02 08:25:59 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
            2018-05-02 08:25:59 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
            2018-05-02 08:26:00 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (146 bytes),
            2018-05-02 08:26:30 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bc03f1b04c9aa4632a89b6570c422c37a.dblock.zip.aes (48,19 MB),
            2018-05-02 08:26:35 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bc03f1b04c9aa4632a89b6570c422c37a.dblock.zip.aes (48,19 MB),
...
        ]
        Warnings: []
        Errors: [
            2018-05-02 08:27:17 -04 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-20180502T032710Z.dlist.zip.aes,
            2018-05-02 08:27:58 -04 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-i623316c958ec4cdaaff6cbc5cebf44cc.dindex.zip.aes,
            2018-05-02 08:28:38 -04 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-bb2acf03d9ee349dab18d764f51cba802.dblock.zip.aes
        ]
DeleteResults:
    DeletedSets: [
        Item1: 1
        Item2: 02/05/2018 00:11:05 (1525234265)
    ]
    Dryrun: False
    MainOperation: Delete
    ParsedResult: Error
    EndTime: 02/05/2018 08:26:37 (1525263997)
    BeginTime: 02/05/2018 08:26:36 (1525263996)
    Duration: 00:00:00.9124560
    Messages: [
        2018-05-02 08:25:59 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
        2018-05-02 08:25:59 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2018-05-02 08:26:00 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (146 bytes),
        2018-05-02 08:26:30 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bc03f1b04c9aa4632a89b6570c422c37a.dblock.zip.aes (48,19 MB),
        2018-05-02 08:26:35 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bc03f1b04c9aa4632a89b6570c422c37a.dblock.zip.aes (48,19 MB),
...
    ]
    Warnings: []
    Errors: [
        2018-05-02 08:27:17 -04 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-20180502T032710Z.dlist.zip.aes,
        2018-05-02 08:27:58 -04 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-i623316c958ec4cdaaff6cbc5cebf44cc.dindex.zip.aes,
        2018-05-02 08:28:38 -04 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-bb2acf03d9ee349dab18d764f51cba802.dblock.zip.aes
    ]
RepairResults: null
TestResults:
    MainOperation: Test
    Verifications: [
        Key: duplicati-20180502T032710Z.dlist.zip.aes
        Value: [
            Key: Error
            Value: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
        ],
        Key: duplicati-i623316c958ec4cdaaff6cbc5cebf44cc.dindex.zip.aes
        Value: [
            Key: Error
            Value: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
        ],
        Key: duplicati-bb2acf03d9ee349dab18d764f51cba802.dblock.zip.aes
        Value: [
            Key: Error
            Value: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
        ]
    ]
    ParsedResult: Error
    EndTime: 02/05/2018 08:28:38 (1525264118)
    BeginTime: 02/05/2018 08:26:37 (1525263997)
    Duration: 00:02:01.0386850
    Messages: [
        2018-05-02 08:25:59 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
        2018-05-02 08:25:59 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2018-05-02 08:26:00 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (146 bytes),
        2018-05-02 08:26:30 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bc03f1b04c9aa4632a89b6570c422c37a.dblock.zip.aes (48,19 MB),
        2018-05-02 08:26:35 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bc03f1b04c9aa4632a89b6570c422c37a.dblock.zip.aes (48,19 MB),
...
    ]
    Warnings: []
    Errors: [
        2018-05-02 08:27:17 -04 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-20180502T032710Z.dlist.zip.aes,
        2018-05-02 08:27:58 -04 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-i623316c958ec4cdaaff6cbc5cebf44cc.dindex.zip.aes,
        2018-05-02 08:28:38 -04 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-bb2acf03d9ee349dab18d764f51cba802.dblock.zip.aes
    ]
ParsedResult: Error
EndTime: 02/05/2018 08:28:38 (1525264118)
BeginTime: 02/05/2018 08:25:59 (1525263959)
Duration: 00:02:39.2693870
Messages: [
    2018-05-02 08:25:59 -04 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: The operation Backup has started,
    2018-05-02 08:25:59 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
    2018-05-02 08:26:00 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (146 bytes),
    2018-05-02 08:26:30 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bc03f1b04c9aa4632a89b6570c422c37a.dblock.zip.aes (48,19 MB),
    2018-05-02 08:26:35 -04 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bc03f1b04c9aa4632a89b6570c422c37a.dblock.zip.aes (48,19 MB),
...
]
Warnings: []
Errors: [
    2018-05-02 08:27:17 -04 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-20180502T032710Z.dlist.zip.aes,
    2018-05-02 08:27:58 -04 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-i623316c958ec4cdaaff6cbc5cebf44cc.dindex.zip.aes,
    2018-05-02 08:28:38 -04 - [Error-Duplicati.Library.Main.Operation.TestHandler-FailedToProcessFile]: Failed to process file duplicati-bb2acf03d9ee349dab18d764f51cba802.dblock.zip.aes
]

Rgds

JonMikelV · May 3, 2018, 8:49pm

It looks like the primary instance of the error is happening during file testing - does the backup step of the job seem to be finishing (for example, can you restore from that datetime / version)? (If so, then the backup is working but the test step is erroring.)

Is it always the same 3 files that show up in the TestResults section? (If so, these may actually be bad files - though the Duplicati should handle the error better.)

duplicati-20180502T032710Z.dlist.zip.aes
duplicati-i623316c958ec4cdaaff6cbc5cebf44cc.dindex.zip.aes
duplicati-bb2acf03d9ee349dab18d764f51cba802.dblock.zip.aes

Just as a test, does the error go away if you add --backup-test-samples=0 to your job? (If so, that confirms it’s the testing step causing the problem.)

--backup-test-samples
After a backup is completed, some files are selected for verification on the remote backend. Use this option to change how many. If this value is set to 0 or the option --no-backend-verification is set, no remote files are verified
Default value: “1”

glaurent · May 7, 2018, 3:29am

Sorry for the delay, I had to redo once again the whole backup from scratch, as the repair + rebuild test messed up the DB, and the backup set was unusable.

On a new backup from scratch, I still have the error:

Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection
which happen on the tests.

But it’s not the same filenames on each attempts, but only on a 3 files set each time.

By setting backup-test-samples = 0, the warning disappears. But is it safe to disable backup test…

Restore is NOT working.
The list of files in the backup set is listed, but restore and on the same Offset … error.
I haven’t tried before, but the restore failes from both of my backup set now.

If you have some test cases to help on this issue, feel free to ask.

I will look to downgrade this week.

glaurent · May 8, 2018, 12:43pm

I finally was able to downgrade to 2.0.2.21_canary_2018-03-06, and everything is working fine.

No more warning, and restore working.

JonMikelV · May 10, 2018, 8:06pm

I wonder if the issue is with the GUI… if/when you upgrade again consider trying a test restore from the command line, just to rule out any possible web UI issues.

glaurent · May 12, 2018, 5:33pm

Not used to the CLI, but I will attempt an upgrade and retri with GUI and CLI.

glaurent · May 14, 2018, 4:01am

So, I tried the CommandLine from the GUI.
Could be nice to display somewhere the executed command line, as it’s quite a pain to add all options and filters…

I reproduised the issue on a small set, only /etc folder backup.

On the Minio / S3 remote, I have 3 files:

duplicati-20180514T034530Z.dlist.zip.aes 197.20 KB May 13, 2018 11:45 PM
duplicati-b9f8f9bb8b3304bde857bc64b1183040f.dblock.zip.aes 3.59 MB May 13, 2018 11:45 PM
duplicati-i9f79e05c7e3f46babc1e3dc8fe515fac.dindex.zip.aes 148.68 KB May 13, 2018 11:45 PM

But the backup verify step failed:

Backup started at 13/05/2018 23:52:54
Checking remote backup …
Listing remote folder …
Scanning local files …
1800 files need to be examined (5,26 MB) (still counting)
0 files need to be examined (0 bytes)
removing temp files, as no data needs to be uploaded
No remote filesets were deleted
Checking remote backup …
Listing remote folder …
removing file listed as Temporary: duplicati-b3879aa69a8ff445994d7c76b047b5d72.dblock.zip.aes
removing file listed as Temporary: duplicati-ia0817900b47f419ba8fff8a96d4af922.dindex.zip.aes
Verifying remote backup …
Remote backup verification completed
Downloading file (197,20 KB) …
Operation Get with file duplicati-20180514T034530Z.dlist.zip.aes attempt 1 of 5 failed with message: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection. => Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
Downloading file (197,20 KB) …
Operation Get with file duplicati-20180514T034530Z.dlist.zip.aes attempt 2 of 5 failed with message: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection. => Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
Downloading file (197,20 KB) …
Operation Get with file duplicati-20180514T034530Z.dlist.zip.aes attempt 3 of 5 failed with message: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection. => Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
Downloading file (197,20 KB) …
Operation Get with file duplicati-20180514T034530Z.dlist.zip.aes attempt 4 of 5 failed with message: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection. => Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
Downloading file (197,20 KB) …
Operation Get with file duplicati-20180514T034530Z.dlist.zip.aes attempt 5 of 5 failed with message: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection. => Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
Failed to process file duplicati-20180514T034530Z.dlist.zip.aes => Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
Downloading file (148,68 KB) …
Operation Get with file duplicati-i9f79e05c7e3f46babc1e3dc8fe515fac.dindex.zip.aes attempt 1 of 5 failed with message: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection. => Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
Downloading file (148,68 KB) …
Operation Get with file duplicati-i9f79e05c7e3f46babc1e3dc8fe515fac.dindex.zip.aes attempt 2 of 5 failed with message: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection. => Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
Downloading file (148,68 KB) …
Operation Get with file duplicati-i9f79e05c7e3f46babc1e3dc8fe515fac.dindex.zip.aes attempt 3 of 5 failed with message: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection. => Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
Downloading file (148,68 KB) …
Operation Get with file duplicati-i9f79e05c7e3f46babc1e3dc8fe515fac.dindex.zip.aes attempt 4 of 5 failed with message: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection. => Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
Downloading file (148,68 KB) …
Operation Get with file duplicati-i9f79e05c7e3f46babc1e3dc8fe515fac.dindex.zip.aes attempt 5 of 5 failed with message: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection. => Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
Failed to process file duplicati-i9f79e05c7e3f46babc1e3dc8fe515fac.dindex.zip.aes => Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
Downloading file (3,59 MB) …
Operation Get with file duplicati-b9f8f9bb8b3304bde857bc64b1183040f.dblock.zip.aes attempt 1 of 5 failed with message: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection. => Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
Downloading file (3,59 MB) …
Operation Get with file duplicati-b9f8f9bb8b3304bde857bc64b1183040f.dblock.zip.aes attempt 2 of 5 failed with message: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection. => Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
Downloading file (3,59 MB) …
Operation Get with file duplicati-b9f8f9bb8b3304bde857bc64b1183040f.dblock.zip.aes attempt 3 of 5 failed with message: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection. => Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
Downloading file (3,59 MB) …
Operation Get with file duplicati-b9f8f9bb8b3304bde857bc64b1183040f.dblock.zip.aes attempt 4 of 5 failed with message: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection. => Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
Downloading file (3,59 MB) …
Operation Get with file duplicati-b9f8f9bb8b3304bde857bc64b1183040f.dblock.zip.aes attempt 5 of 5 failed with message: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection. => Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
Failed to process file duplicati-b9f8f9bb8b3304bde857bc64b1183040f.dblock.zip.aes => Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
Duration of backup: 00:02:02
Remote files: 3
Remote size: 3,92 MB
Total remote quota: 0 bytes
Available remote quota: 0 bytes
Files added: 0
Files deleted: 0
Files changed: 0
Data uploaded: 0 bytes
Data downloaded: 0 bytes
Backup completed successfully!
Return code: 3

I don’t know what is expecting Duplicati…

JonMikelV · May 17, 2018, 5:53pm

For backups you can use “Export …” in the job menu then select “As Command-line”.

Was was this still on the 2.0.2.21 version that had been working for you or was it using a newer version?

You’ve provided more detail on this than I’ve seen before, so perhaps @kenkendk or @Pectojin might have a thought about why all 3 blockset files (dindex, dlist, and dblock) each failed 5 download attempts from S3 with the same “Offset and length were out of bounds” error…

glaurent · May 17, 2018, 6:49pm

Hi,

I reproduced the issue (well, can’t really say reproduce, as I do not know why it goes this way) on my 2nd desktop.
It’s now running 2.0.3.3_beta_2018-04-02, with the same backup set of /etc (~ 4MB) to 2 destinations : B2 and Minio (S3 like).
And sadly, both backups failed at the 1st attempt. So there only 3 files on each remote destination, and the test is failing the same way.
I don’t care of the backups for this computer, so if you have some tests to run for this issue, let me know.
Rgds,

JonMikelV · May 22, 2018, 9:00pm

I’m assuming these new failures on 2.0.3.3 again go away if you set --backup-test-samples=0 and that you can’t restore from them using the normal job “Restore files…” link.

If you use the main menu Restore link then select “Direct restore from backup files…” or “Restore from configuration…” (assuming you have an exported .json config file floating around) does adding --backup-test-samples=0 to the “Advanced options” section allow restores? (Note that you’ll need to use the “3 dots” menu on the right to select “Edit as text”.)

glaurent · May 23, 2018, 3:20pm

Hum, failed too with:

Messages: [
Rebuild database started, downloading 1 filelists,
Recreate/path-update completed, not running consistency checks
]
Warnings: [
Failed to process file: duplicati-20180523T125240Z.dlist.zip.aes => Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
]

JonMikelV · May 28, 2018, 4:59pm

Unfortunately, I don’t have any more thoughts at the moment.

However, you’re not the only person to have reported this error (though I’m not sure they’re all from the same cause) - perhaps @kenkendk or @Pectojin might have some insight.

kenkendk · June 8, 2018, 11:06am

Do you happen to have a stack trace as well? It should show up in the log area for the backup.

The error happens in the Get code, but I am unsure if it happens in the S3 code or in some of the other code. A quick guess could be that the option --disable-piped-streaming would prevent the error?

glaurent · June 10, 2018, 2:10am

Hi,

Just run a new backup to get fresh logs.

First error is a Retry, 5x:

Operation Get with file duplicati-b07b5806f458a49689395bef3499fd392.dblock.zip.aes attempt 1 of 5 failed with message: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
System.ArgumentException: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
at System.Buffer.BlockCopy (System.Array src, System.Int32 srcOffset, System.Array dst, System.Int32 dstOffset, System.Int32 count) [0x000b1] in <8f2c484307284b51944a1a13a14c0266>:0
at System.Security.Cryptography.HashAlgorithm.TransformBlock (System.Byte inputBuffer, System.Int32 inputOffset, System.Int32 inputCount, System.Byte outputBuffer, System.Int32 outputOffset) [0x000a1] in <8f2c484307284b51944a1a13a14c0266>:0
at System.Security.Cryptography.CryptoStream.Write (System.Byte buffer, System.Int32 offset, System.Int32 count) [0x001c0] in <8f2c484307284b51944a1a13a14c0266>:0
at Duplicati.Library.Utility.ShaderStream.Write (System.Byte buffer, System.Int32 offset, System.Int32 count) [0x00000] in <0828ce86ffa94a4bbbb2da4331bcc67b>:0
at Duplicati.Library.Utility.ThrottledStream.Write (System.Byte buffer, System.Int32 offset, System.Int32 count) [0x00047] in <0828ce86ffa94a4bbbb2da4331bcc67b>:0
at Duplicati.Library.Utility.OverrideableStream.Write (System.Byte buffer, System.Int32 offset, System.Int32 count) [0x00000] in <0828ce86ffa94a4bbbb2da4331bcc67b>:0
at Duplicati.Library.Utility.ProgressReportingStream.Write (System.Byte buffer, System.Int32 offset, System.Int32 count) [0x00006] in <0828ce86ffa94a4bbbb2da4331bcc67b>:0
at Duplicati.Library.Utility.Utility.CopyStream (System.IO.Stream source, System.IO.Stream target, System.Boolean tryRewindSource, System.Byte buf) [0x0002c] in <0828ce86ffa94a4bbbb2da4331bcc67b>:0
at Duplicati.Library.Utility.Utility.CopyStream (System.IO.Stream source, System.IO.Stream target) [0x00000] in <0828ce86ffa94a4bbbb2da4331bcc67b>:0
at Duplicati.Library.Backend.Backblaze.B2.Get (System.String remotename, System.IO.Stream stream) [0x000b1] in <744672e2da8444bdaaf10c5b0487d731>:0

Then the Message:

Failed to process file duplicati-b07b5806f458a49689395bef3499fd392.dblock.zip.aes
System.ArgumentException: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
at Duplicati.Library.Main.BackendManager.GetForTesting (System.String remotename, System.Int64 size, System.String hash) [0x00065] in :0
at Duplicati.Library.Main.Operation.TestHandler.DoRun (System.Int64 samples, Duplicati.Library.Main.Database.LocalTestDatabase db, Duplicati.Library.Main.BackendManager backend) [0x003f7] in :0

And the Result:

DeletedFiles: 0
DeletedFolders: 0
ModifiedFiles: 5
ExaminedFiles: 2265
OpenedFiles: 5
AddedFiles: 0
SizeOfModifiedFiles: 480
SizeOfAddedFiles: 0
SizeOfExaminedFiles: 9447669
SizeOfOpenedFiles: 162595
NotProcessedFiles: 0
AddedFolders: 0
TooLargeFiles: 0
FilesWithError: 0
ModifiedFolders: 0
ModifiedSymlinks: 0
AddedSymlinks: 0
DeletedSymlinks: 0
PartialBackup: False
Dryrun: False
MainOperation: Backup
CompactResults:
DeletedFileCount: 0
DownloadedFileCount: 0
UploadedFileCount: 0
DeletedFileSize: 0
DownloadedFileSize: 0
UploadedFileSize: 0
Dryrun: False
MainOperation: Compact
ParsedResult: Success
EndTime: 09/06/2018 21:57:37 (1528595857)
BeginTime: 09/06/2018 21:57:37 (1528595857)
Duration: 00:00:00.0325100
BackendStatistics:
RemoteCalls: 20
BytesUploaded: 206263
BytesDownloaded: 0
FilesUploaded: 3
FilesDownloaded: 0
FilesDeleted: 0
FoldersCreated: 0
RetryAttempts: 12
UnknownFileSize: 0
UnknownFileCount: 0
KnownFileCount: 45
KnownFileSize: 5446345
LastBackupDate: 09/06/2018 21:57:31 (1528595851)
BackupListCount: 7
TotalQuotaSpace: 0
FreeQuotaSpace: 0
AssignedQuotaSpace: -1
ReportedQuotaError: False
ReportedQuotaWarning: False
ParsedResult: Success
DeleteResults:
DeletedSets:
Dryrun: False
MainOperation: Delete
ParsedResult: Success
EndTime: 09/06/2018 21:57:37 (1528595857)
BeginTime: 09/06/2018 21:57:37 (1528595857)
Duration: 00:00:00.0740260
RepairResults: null
TestResults:
MainOperation: Test
Verifications: [
Key: duplicati-20180605T230000Z.dlist.zip.aes
Value: [
Key: Error
Value: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
],
Key: duplicati-i1da5076cd7934313ad4f03912ca1971f.dindex.zip.aes
Value: [
Key: Error
Value: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
],
Key: duplicati-b07b5806f458a49689395bef3499fd392.dblock.zip.aes
Value: [
Key: Error
Value: Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
]
]
ParsedResult: Success
EndTime: 09/06/2018 22:00:00 (1528596000)
BeginTime: 09/06/2018 21:57:38 (1528595858)
Duration: 00:02:21.9731980
ParsedResult: Error
EndTime: 09/06/2018 22:00:00 (1528596000)
BeginTime: 09/06/2018 21:57:31 (1528595851)
Duration: 00:02:29.0538150
Messages: [
No remote filesets were deleted,
Compacting not required
]
Warnings:
Errors: [
Failed to process file duplicati-20180605T230000Z.dlist.zip.aes => Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.,
Failed to process file duplicati-i1da5076cd7934313ad4f03912ca1971f.dindex.zip.aes => Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.,
Failed to process file duplicati-b07b5806f458a49689395bef3499fd392.dblock.zip.aes => Offset and length were out of bounds for the array or count is greater than the number of elements from index to the end of the source collection.
]

The remote list provide:

[
{“Name”:“duplicati-20180514T034106Z.dlist.zip.aes”,“LastAccess”:“2018-05-14T03:41:24Z”,“LastModification”:“2018-05-14T03:41:24Z”,“Size”:201933,“IsFolder”:false},
{“Name”:“duplicati-20180522T235313Z.dlist.zip.aes”,“LastAccess”:“2018-05-22T23:55:19Z”,“LastModification”:“2018-05-22T23:55:19Z”,“Size”:202125,“IsFolder”:false},
{“Name”:“duplicati-20180531T015046Z.dlist.zip.aes”,“LastAccess”:“2018-05-31T01:50:48Z”,“LastModification”:“2018-05-31T01:50:48Z”,“Size”:202189,“IsFolder”:false},
{“Name”:“duplicati-20180603T170000Z.dlist.zip.aes”,“LastAccess”:“2018-06-03T17:00:05Z”,“LastModification”:“2018-06-03T17:00:05Z”,“Size”:202253,“IsFolder”:false},
{“Name”:“duplicati-20180605T230000Z.dlist.zip.aes”,“LastAccess”:“2018-06-05T23:00:06Z”,“LastModification”:“2018-06-05T23:00:06Z”,“Size”:202253,“IsFolder”:false},
{“Name”:“duplicati-20180607T030000Z.dlist.zip.aes”,“LastAccess”:“2018-06-07T03:00:06Z”,“LastModification”:“2018-06-07T03:00:06Z”,“Size”:202189,“IsFolder”:false},
{“Name”:“duplicati-20180610T015731Z.dlist.zip.aes”,“LastAccess”:“2018-06-10T01:57:31Z”,“LastModification”:“2018-06-10T01:57:31Z”,“Size”:202205,“IsFolder”:false},
{“Name”:“duplicati-b02f5b3d9e0874c85806aa451e45ac780.dblock.zip.aes”,“LastAccess”:“2018-06-02T15:00:04Z”,“LastModification”:“2018-06-02T15:00:04Z”,“Size”:2781,“IsFolder”:false},
{“Name”:“duplicati-b07b5806f458a49689395bef3499fd392.dblock.zip.aes”,“LastAccess”:“2018-05-21T05:00:02Z”,“LastModification”:“2018-05-21T05:00:02Z”,“Size”:2317,“IsFolder”:false},
{“Name”:“duplicati-b1cf9ddaa0a80405d9fb4288597912ac9.dblock.zip.aes”,“LastAccess”:“2018-05-22T23:55:19Z”,“LastModification”:“2018-05-22T23:55:19Z”,“Size”:5485,“IsFolder”:false},
{“Name”:“duplicati-b211e2647743d43158f992096f524994f.dblock.zip.aes”,“LastAccess”:“2018-06-03T17:00:03Z”,“LastModification”:“2018-06-03T17:00:03Z”,“Size”:5565,“IsFolder”:false},
{“Name”:“duplicati-b2614646ae74549ce8cb4b6d8be9170b8.dblock.zip.aes”,“LastAccess”:“2018-05-14T03:41:13Z”,“LastModification”:“2018-05-14T03:41:13Z”,“Size”:3760717,“IsFolder”:false},
{“Name”:“duplicati-b2e2bb798371e4c45a8774232306770c1.dblock.zip.aes”,“LastAccess”:“2018-05-31T19:00:04Z”,“LastModification”:“2018-05-31T19:00:04Z”,“Size”:2141,“IsFolder”:false},
{“Name”:“duplicati-b370561c4a0754c86bb73044ada7a506b.dblock.zip.aes”,“LastAccess”:“2018-05-19T15:37:50Z”,“LastModification”:“2018-05-19T15:37:50Z”,“Size”:5005,“IsFolder”:false},
{“Name”:“duplicati-b3d2e8eae40a2424e9ae39d58647aebb9.dblock.zip.aes”,“LastAccess”:“2018-05-26T01:46:31Z”,“LastModification”:“2018-05-26T01:46:31Z”,“Size”:5949,“IsFolder”:false},
{“Name”:“duplicati-b448c7acd5cb641b4b28f615496d041e8.dblock.zip.aes”,“LastAccess”:“2018-05-31T18:08:07Z”,“LastModification”:“2018-05-31T18:08:07Z”,“Size”:10685,“IsFolder”:false},
{“Name”:“duplicati-b481249ce36a34736b7b121d51d2ad64a.dblock.zip.aes”,“LastAccess”:“2018-06-05T23:00:03Z”,“LastModification”:“2018-06-05T23:00:03Z”,“Size”:2877,“IsFolder”:false},
{“Name”:“duplicati-b5f2ed5692e424f8faf463e1e597effeb.dblock.zip.aes”,“LastAccess”:“2018-05-26T03:00:03Z”,“LastModification”:“2018-05-26T03:00:03Z”,“Size”:2781,“IsFolder”:false},
{“Name”:“duplicati-b677c5984ee8349999edd50ba68bd9279.dblock.zip.aes”,“LastAccess”:“2018-05-31T01:50:45Z”,“LastModification”:“2018-05-31T01:50:45Z”,“Size”:4157,“IsFolder”:false},
{“Name”:“duplicati-b72d380688da54f35bf1591c95d904152.dblock.zip.aes”,“LastAccess”:“2018-05-31T03:00:03Z”,“LastModification”:“2018-05-31T03:00:03Z”,“Size”:4493,“IsFolder”:false},
{“Name”:“duplicati-b7c5f09b248e141ac9c0855f804d6960c.dblock.zip.aes”,“LastAccess”:“2018-05-23T12:52:43Z”,“LastModification”:“2018-05-23T12:52:43Z”,“Size”:4029,“IsFolder”:false},
{“Name”:“duplicati-b7ff85e8f373a42d2b3b55ed90076f28a.dblock.zip.aes”,“LastAccess”:“2018-06-10T01:57:29Z”,“LastModification”:“2018-06-10T01:57:29Z”,“Size”:2893,“IsFolder”:false},
{“Name”:“duplicati-bd0f54e7d5b1348129655b2781d50b5e3.dblock.zip.aes”,“LastAccess”:“2018-06-07T03:00:02Z”,“LastModification”:“2018-06-07T03:00:02Z”,“Size”:11181,“IsFolder”:false},
{“Name”:“duplicati-be9062583e321496f846fa9a973f49feb.dblock.zip.aes”,“LastAccess”:“2018-05-21T00:17:54Z”,“LastModification”:“2018-05-21T00:17:54Z”,“Size”:14301,“IsFolder”:false},
{“Name”:“duplicati-beaf8c8cf73c343e0b8b5f1acdd7d7478.dblock.zip.aes”,“LastAccess”:“2018-06-02T14:10:18Z”,“LastModification”:“2018-06-02T14:10:18Z”,“Size”:4157,“IsFolder”:false},
{“Name”:“duplicati-bfa3a58e3707c4d8f95a48fbe4abd42c6.dblock.zip.aes”,“LastAccess”:“2018-05-21T01:00:02Z”,“LastModification”:“2018-05-21T01:00:02Z”,“Size”:2781,“IsFolder”:false},
{“Name”:“duplicati-i1a063910943b4977bd05f1e3d00eea6b.dindex.zip.aes”,“LastAccess”:“2018-05-22T23:55:19Z”,“LastModification”:“2018-05-22T23:55:19Z”,“Size”:1421,“IsFolder”:false},
{“Name”:“duplicati-i1da5076cd7934313ad4f03912ca1971f.dindex.zip.aes”,“LastAccess”:“2018-05-21T05:00:03Z”,“LastModification”:“2018-05-21T05:00:03Z”,“Size”:1085,“IsFolder”:false},
{“Name”:“duplicati-i20a3d046fee7425c9870a5a36a3c894e.dindex.zip.aes”,“LastAccess”:“2018-05-26T01:46:34Z”,“LastModification”:“2018-05-26T01:46:34Z”,“Size”:1517,“IsFolder”:false},
{“Name”:“duplicati-i35050d663d6c4e2b981ce2abdc76592f.dindex.zip.aes”,“LastAccess”:“2018-05-31T03:00:03Z”,“LastModification”:“2018-05-31T03:00:03Z”,“Size”:1373,“IsFolder”:false},
{“Name”:“duplicati-i49a54b79501d450c987324c5eb7ccd9a.dindex.zip.aes”,“LastAccess”:“2018-06-02T15:00:04Z”,“LastModification”:“2018-06-02T15:00:04Z”,“Size”:1165,“IsFolder”:false},
{“Name”:“duplicati-i4b07bcb7cdec45d0bf9d9d766082be59.dindex.zip.aes”,“LastAccess”:“2018-06-02T14:10:19Z”,“LastModification”:“2018-06-02T14:10:19Z”,“Size”:1309,“IsFolder”:false},
{“Name”:“duplicati-i57f62a1b219a4939948127aa0730057e.dindex.zip.aes”,“LastAccess”:“2018-05-23T12:52:46Z”,“LastModification”:“2018-05-23T12:52:46Z”,“Size”:1229,“IsFolder”:false},
{“Name”:“duplicati-i5f7a551ebd4345e8b1db5e3e3dc64edc.dindex.zip.aes”,“LastAccess”:“2018-05-21T01:00:03Z”,“LastModification”:“2018-05-21T01:00:03Z”,“Size”:1149,“IsFolder”:false},
{“Name”:“duplicati-i76fe972371dc40219f530301c7c69f81.dindex.zip.aes”,“LastAccess”:“2018-06-10T01:57:30Z”,“LastModification”:“2018-06-10T01:57:30Z”,“Size”:1165,“IsFolder”:false},
{“Name”:“duplicati-i7a01f6ab10d8469e9f95483d98cd42fb.dindex.zip.aes”,“LastAccess”:“2018-06-07T03:00:04Z”,“LastModification”:“2018-06-07T03:00:04Z”,“Size”:1661,“IsFolder”:false},
{“Name”:“duplicati-i7ce0f81565c24544aeffaa94724b4b4c.dindex.zip.aes”,“LastAccess”:“2018-05-26T03:00:04Z”,“LastModification”:“2018-05-26T03:00:04Z”,“Size”:1149,“IsFolder”:false},
{“Name”:“duplicati-i815c0c6ad23e492094aeb7085f1927db.dindex.zip.aes”,“LastAccess”:“2018-05-31T18:08:07Z”,“LastModification”:“2018-05-31T18:08:07Z”,“Size”:2045,“IsFolder”:false},
{“Name”:“duplicati-i8cc2c5d63683418ea1509518dc6da2e8.dindex.zip.aes”,“LastAccess”:“2018-05-19T15:37:51Z”,“LastModification”:“2018-05-19T15:37:51Z”,“Size”:1421,“IsFolder”:false},
{“Name”:“duplicati-i9e58d56f1ad84898882d35cfd7909757.dindex.zip.aes”,“LastAccess”:“2018-05-14T03:41:22Z”,“LastModification”:“2018-05-14T03:41:22Z”,“Size”:152253,“IsFolder”:false},
{“Name”:“duplicati-ibdadc79e177341d7bef8bf99ffec3848.dindex.zip.aes”,“LastAccess”:“2018-05-31T19:00:06Z”,“LastModification”:“2018-05-31T19:00:06Z”,“Size”:1069,“IsFolder”:false},
{“Name”:“duplicati-icbe9311cd35c41aba6cb4610eb55fa46.dindex.zip.aes”,“LastAccess”:“2018-06-05T23:00:04Z”,“LastModification”:“2018-06-05T23:00:04Z”,“Size”:1165,“IsFolder”:false},
{“Name”:“duplicati-ie4c5688719d54152b06a5b191f86c864.dindex.zip.aes”,“LastAccess”:“2018-05-31T01:50:46Z”,“LastModification”:“2018-05-31T01:50:46Z”,“Size”:1309,“IsFolder”:false},
{“Name”:“duplicati-ie7be13abe2b3479caf0e6487ce9f3de8.dindex.zip.aes”,“LastAccess”:“2018-05-21T00:17:54Z”,“LastModification”:“2018-05-21T00:17:54Z”,“Size”:1965,“IsFolder”:false},
{“Name”:“duplicati-ifd34a44a2a9143b591a94bdcad5078f3.dindex.zip.aes”,“LastAccess”:“2018-06-03T17:00:05Z”,“LastModification”:“2018-06-03T17:00:05Z”,“Size”:1453,“IsFolder”:false}
]

The file duplicati-b07b5806f458a49689395bef3499fd392.dblock.zip.aes is present on the B2 bucket.

And sadly, the option disable-piped-streaming is set as default setting.

Let me know if you need other logs or information.

Rgds,

mortisj · July 13, 2018, 2:56pm

Hi all:

I’m having the same problem as described above, although I am using an SFTP backend. Other than that the stack trace is the same.

I’ve discovered that for me at least the problem only occurs when disable-piped-streaming=true. If I set disable-piped-streaming=false the problem goes away.

Curiously the reason I was using disable-piped-streaming=true in the first place is because in version 2.0.2 I was getting the same array bounds error with disable-piped-stream=false!

I put some debug code into ShaderStream.Write (the highest Duplicati code in the stack trace) and found the the buffer, offset, and length variables all looked OK. I’d guess there is a bug in the System.Security.Crypto modules that is causing the problem, presumably by incorrectly shortening the buffer. I’m running under Ubuntu 12.04 and Mono 5.12 if that is relevant.

The process used for decrypting a downloaded file now seems to be quite different depending on the value of disable-piped-stream. It looks like the newer process used when disable-piped-stream=false is more reliable than the older method still used when disable-piped-streaming=true. It might be time to update the latter, but not knowing the history behind it all I’m reluctant to try doing that myself.

Cheers.

JonMikelV · July 13, 2018, 5:45pm

Thanks for the detailed research into the issue!

I see this showing up from time to time on a Mac, but it’s very infrequent for me (I’m using the default piped-streaming value).

If he has some time maybe @kenkendk can let us know if there’s any history that needs to be considered in those to code branches.

OecherWolke · April 11, 2022, 7:44am

Old thread, but the problem is still present in 2022.
I can confirm this. Running 2.0.6.3_beta_2021-06-17 on two MacOS X machines (10.13.6 & 10.15.7) and on another machine with Duplicati in a docker container (DSM 6 on a Synology NAS).

“disable-piped-streaming” was set to true on all three machines. Set it back to false (default), errors disappeared on all machines.