SaveProgress reported progress regresses

[serpens24]

The following sample code is used to demonstrate my issue with some logging added.

I have a function which adds a heap of content to a directory to be backed up, and then uses DotNetZip 1.16.0 NuGet to add this to a zip. I am using encryption on the zip, and alsp reporting progress to a GUI which manages the backup.

I am finding that "for some examples" the e.BytesTransferred reported in the ZipProgressEventType.Saving_EntryBytesRead SaveProgress case are going backwards. When digging deeper, it appears that the files in question get all the way through, but are then processed a second time, meaning that the e.BytesTransferred returns to 0.

The implication of this is my progress bar jumps backwards. To mitigate this, I've added some code to check if the reported progress %complete is incrementing and I only report successful increments.

`

        long processedSize = 0;
        using (ZipFile zip = new ZipFile())
        {
            // I found a few cases where Ionic.zip e.BytesTransferred value reported in ZipProgressEventType.Saving_EntryBytesRead drops - it seems that it gets to the end of
            // the file and then re-adds it - if I let this happen the progress bar jumps backwards, so keep track of last reported progress and only update if progress has
            // been made.
            double lastPercentComplete = 0.0;

            // Define inline function to handle progress updates received from zip operation and use them to update GUI with call to progress.Report().
            zip.SaveProgress += (sender, e) => {
                if (e.EventType == ZipProgressEventType.Saving_BeforeWriteEntry)
                {
                    Log.Error($"Saving_BeforeWriteEntry: starting fileName={e.CurrentEntry.FileName}");
                }
                else if (e.EventType == ZipProgressEventType.Saving_EntryBytesRead)
                {
                    Log.Error($"Saving_EntryBytesRead bytesTransferred={e.BytesTransferred}");

                    // Calculate intermediate progress as file is processed
                    double percentComplete = 100.0 * ((double)(processedSize + e.BytesTransferred) / (double)(expectedUncompressedSize));
                    if (percentComplete >= 100.0)
                    {
                        Log.Error($"Saving_EntryBytesRead: file transfer >= 100.000%: bytesTransferred={e.BytesTransferred}");
                    }
                    if (lastPercentComplete > percentComplete)
                    {
                        Log.Error($"Saving_EntryBytesRead: progress regressed: fileName={e.CurrentEntry.FileName} ### {percentComplete:F3}% < {lastPercentComplete:F3}%");
                    }
                    percentComplete = percentComplete > lastPercentComplete ? percentComplete : lastPercentComplete;
                    lastPercentComplete = percentComplete;
                    if (progress != null) { progress.Report(percentComplete); }
                }
                else if (e.EventType == ZipProgressEventType.Saving_AfterWriteEntry)
                {
                    processedSize += e.CurrentEntry.UncompressedSize;  // The file has been written, increase processedSize to reflect this
                    Log.Error($"Saving_AfterWriteEntry: completed fileName={e.CurrentEntry.FileName} : uncompressedSize={e.CurrentEntry.UncompressedSize}");
                    double percentComplete = 100.0 * (processedSize / expectedUncompressedSize);
                    lastPercentComplete = percentComplete;
                    progress.Report(percentComplete);
                }
            };
            zip.Comment = "Backup created " + DateTime.UtcNow.ToString();
            zip.Password = cypher;
            zip.Encryption = EncryptionAlgorithm.WinZipAes256;
            zip.AddDirectory(srcDirectory);
            zip.Save(backupFilePath);
        }

`

An example of the produced output is below:

`

2023-09-12 08:46:14.528 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_BeforeWriteEntry: starting fileName=file1.json
2023-09-12 08:46:14.531 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead bytesTransferred=2
2023-09-12 08:46:14.531 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_AfterWriteEntry: completed fileName=file1.json : uncompressedSize=2
2023-09-12 08:46:14.531 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_BeforeWriteEntry: starting fileName=file2.json
2023-09-12 08:46:14.536 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead bytesTransferred=592
2023-09-12 08:46:14.537 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_AfterWriteEntry: completed fileName=file2.json : uncompressedSize=592
2023-09-12 08:46:14.537 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_BeforeWriteEntry: starting fileName=file3.json
2023-09-12 08:46:14.540 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead bytesTransferred=1052
2023-09-12 08:46:14.540 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_AfterWriteEntry: completed fileName=file3.json : uncompressedSize=1052

removed multiple other successful files

the following is a larger file with multiple Saving_EntryBytesRead calls which also works - and is the normal case

2023-09-12 08:46:14.551 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_BeforeWriteEntry: starting fileName=file4.big
2023-09-12 08:46:14.563 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead bytesTransferred=32768
2023-09-12 08:46:14.563 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead bytesTransferred=65536
2023-09-12 08:46:14.564 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead bytesTransferred=98304
2023-09-12 08:46:14.564 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead bytesTransferred=131072

removed multiple lines as file is processed

2023-09-12 08:46:16.174 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead bytesTransferred=42762240
2023-09-12 08:46:16.175 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead bytesTransferred=42795008
2023-09-12 08:46:16.175 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead bytesTransferred=42816784
2023-09-12 08:46:16.181 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_AfterWriteEntry: completed fileName=file4.big: uncompressedSize=42816784

the following is a larger file with multiple Saving_EntryBytesRead calls which copies all the way through, but then starts the copy of the file again

2023-09-12 08:46:25.002 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_BeforeWriteEntry: starting fileName=file5.zip
2023-09-12 08:46:25.007 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead bytesTransferred=32768
2023-09-12 08:46:25.007 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead bytesTransferred=65536
2023-09-12 08:46:25.008 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead bytesTransferred=98304

removed multiple lines as file is processed

2023-09-12 08:46:25.164 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead bytesTransferred=3375104
2023-09-12 08:46:25.164 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead bytesTransferred=3407872
2023-09-12 08:46:25.164 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead bytesTransferred=3411357
2023-09-12 08:46:25.164 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead: file transfer >= 100.000%: bytesTransferred=3411357

At this point the bytesTransferred reports 3411357 whichis the file size, but the next line shows value back at 32768

2023-09-12 08:46:25.177 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead bytesTransferred=32768
2023-09-12 08:46:25.177 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead: progress regressed: fileName=file5.zip ### 98.593% < 100.000%
2023-09-12 08:46:25.179 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead bytesTransferred=65536
2023-09-12 08:46:25.179 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead: progress regressed: fileName=file5.zip ### 98.607% < 100.000%
2023-09-12 08:46:25.181 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead bytesTransferred=98304

removed multiple lines as file is processed and re-copied? with warnings each time that we had previously got further with it

2023-09-12 08:46:25.337 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead: progress regressed: fileName=file5.zip ### 99.985% < 100.000%
2023-09-12 08:46:25.338 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead bytesTransferred=3407872
2023-09-12 08:46:25.338 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead: progress regressed: fileName=file5.zip ### 99.999% < 100.000%
2023-09-12 08:46:25.338 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead bytesTransferred=3411357
2023-09-12 08:46:25.338 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_EntryBytesRead: file transfer >= 100.000%: bytesTransferred=3411357
2023-09-12 08:46:25.339 [EROR] BackupManager+<>c__DisplayClass53_1.b__0: Saving_AfterWriteEntry: completed fileName=file5.zip : uncompressedSize=3411357
`

I am trying to determine if I am using the SaveProgress functionality correctly, or if something else is at play here.