EOF issue with zfsbackup-go

[lhoward]

Let me preface this by saying that I am not a Go programmer, nor an expert on B2; just a humble punter trying to get zfsbackup-go working on my Solaris machine. I don't know enough to know whether this issue is in zfsbackup-go's usage of Blazer, or in Blazer itself.

cf someone1/zfsbackup-go#17

ListObjects() in Writer.getLargeFile() could return EOF, which was causing zfsbackup-go to hang starting a new upload. Treating EOF identically to len(objs) < 1 (i.e. restarting with w.Resume = false) seemed to fix it, but I'm not sure if this is the correct fix.

diff --git a/b2/writer.go b/b2/writer.go
index 209cfce..bedf626 100644
--- a/b2/writer.go
+++ b/b2/writer.go
@@ -311,7 +311,12 @@ func (w *Writer) getLargeFile() (beLargeFileInterface, error) {
                cur := &Cursor{name: w.name}
                objs, _, err := w.o.b.ListObjects(w.ctx, 1, cur)
                if err != nil {
-                       return nil, err
+                       if err == io.EOF {
+                               w.Resume = false
+                               return w.getLargeFile()
+                       } else {
+                               return nil, err
+                       }
                }
                if len(objs) < 1 || objs[0].name != w.name {
                        w.Resume = false

[kurin]

This feels like an issue in Blazer but let me see if I can get a test case failing. This code is possibly more complicated than it ought to be 🙄

[kurin]

I suspect you've surfaced a bug where if Resume is true but there's nothing to resume it just blows up.

[kurin]

Thanks for catching this! Try with the latest commit, you should be good.

[someone1]

Apologies for the tardy chiming in - I added that bit since retries after a network failure would result in incomplete open large file uploads. When I made the change I thought blazer would know to start a new file if there was nothing to resume (may have just read the code wrong at the time!)

Anyway, thanks for all the debugging @lhoward and for the quick fix @kurin !

[lhoward]

This fix unfortunately gets it stuck in an endless loop with

2019/01/26 15:48:19 b2: Opening volume tank/Git|20190126.zstream.gz.pgp.vol1
2019/01/26 15:48:19 b2 backend: Entering tank/Git|20190126.zstream.gz.pgp.vol1
2019/01/26 15:48:19 b2 backend: Uploading tank/Git|20190126.zstream.gz.pgp.vol1
2019/01/26 15:48:19 b2 backend: Error while uploading volume tank/Git|20190126.zstream.gz.pgp.vol1 - context canceled
2019/01/26 15:48:19 b2: Error while uploading volume tank/Git|20190126.zstream.gz.pgp.vol1 - context canceled

[kurin]

Does this happen with any invocation? I have a zfs box around here somewhere I can try to test this on, but if you can reproduce it with the environment variable B2_LOG_LEVEL=2 you'll get a lot of debug lines that you could add to the bug (be sure to purge of secret data).

[lhoward]

I wasn't exactly sure what data to consider secret, so for now I'll just paste in a summary – happy to send you the complete details privately if you mail me (lukeh at padl.com).

• b2_list_unfinished_large_files (returns a fileId, nextFileId == null)
• b2_list_parts (returns a bunch)
• b2_get_upload_part_url (returns upload URLs for a bunch of fileIDs)

The key appears to be this ("chunks don't match"):

2019/01/26 18:21:44 error writing tank/Git|20190126.zstream.gz.pgp.vol1: resumable upload was requested, but chunks don't match
2019/01/26 18:21:44 << b2_get_upload_part_url (14) 200  {Cache-Control: max-age=0, no-cache, no-store; Content-Type: application/json;charset=utf-8; Content-Length: 376; Date: Sat, 26 Jan 2019 07:31:33 GMT} ({
  "authorizationToken": "[redacted]",
  "fileId": "some-fileid-redacted",
  "uploadUrl": "https://pod-000-1118-16.backblaze.com/b2api/v1/b2_upload_part/some-fileid-redacted/0055"
}
)
2019/01/26 18:21:44 >> b2_finish_large_file uri: https://api002.backblazeb2.com/b2api/v1/b2_finish_large_file headers: {X-Blazer-Request-Id: 17;User-Agent: blazer/0.5.1} args: ({"fileId":"some-fileid-redacted","partSha1Array":["67a935b099a061116bed27ba1ea8403fc3fe50e4","71dc3437d1dfa17cf36e1da1d9373fc875bd37ce","b5c1c32096584dce8837ee26c0d371d6a69b6bd5","826363c88715be8e4aa2190c91e0c0bfed4b7941","a36bdad6cc27bfa4e26a69a3501ad409a3e999f2","780c49397e0f2d64d7012eeeffe293308a2376c1","a6a79531a551b1ca2f0e9c0287da78d2fd456ed6","cb8ae6c70cd4f7b7e7593aa6c011c966a6224c69","fb3ddd9a9e2d32bb8c676025f43e3c8133a9fc5e","53ce7c6a8f6da7a9d6fdefdac4e95066b38a8cea"]})
2019/01/26 18:21:44 b2 backend: Error while uploading volume tank/Git|20190126.zstream.gz.pgp.vol1 - context canceled
2019/01/26 18:21:44 b2: Error while uploading volume tank/Git|20190126.zstream.gz.pgp.vol1 - context canceled

[kurin]

Oooh okay so what's happening is that to resume the large file, the checksums of the already-uploaded chunks have to match the checksums of the corresponding chunks of the current file; if not you're really uploading a different file.

The reason your checksums don't match, I'm pretty sure, is because the snapshot you're uploading is encrypted, and the encryption is of course resulting in a different data stream each time.

This library is designed so that clients who receive errors will by default simply retry forever; the only permanent failure should be if the process itself dies. @someone1 do you have examples of the kinds of failures that led you to set w.Resume = true?

I need to think about whether there's a better way to handle non-matching resumes. I think it might be a good idea to add an option, when there's a conflict, to remove the partially uploaded file and start from scratch.

[lhoward]

So setting resume to false should fix it? There is a resume command line option to zfsbackup BTW but I’m not setting that. And yes I am encrypting.

[lhoward]

Is this resuming within or across a zfsbackup session, I wonder? In the latter case it seems like it should be disabled if encryption is on (even if it’s off, unless the volumes are cached locally possibly an unencrypted backup may differ?) just speculating.

[kurin]

I'm not familiar with zfsbackup-go but it sounds to me like it's starting the upload from the beginning with w.Resume = true, which works when the stream is the same, but fails when the stream is encrypted, because the same plaintext becomes different cyphertext.

I'm wondering what's happening to cause zfsbackup-go to restart from the beginning, however, because that shouldn't be necessary. If the backup is interrupted (e.g. if the network drops), the client should just hang until service is restored.

[lhoward]

If in zfsbackup-go's B2Backend.Upload(), I set w.Resume to false, the backup completes. @someone1 are there any risks in making this change?

[someone1]

@kurin - I think it was a mistake to add Resume=true as the default option in zfsbackup-go precisely for the reason you described. I had a user complain that they saw multiple versions of files in their B2 buckets where some were not accessible and assumed this was due to incomplete large file uploads. I don't actually see a way in blazer to cancel a large file upload and my goal was to just resume or start a new upload.

I think it would make sense to provide the following in the blazer:

• If a large file upload fails for whatever reason and an option such as AbortOnFailure=true, then blazer should automatically cancel the large file upload.
• Add an option as you described to clear out any partially uploaded files when starting an upload (this should obviously be mutually exclusive to the Resume option).

I'd love to have my code better tested against B2 - the bonfire package you have seems interesting in this regard - can it be used to setup a local B2 emulator to write tests against? If so, mind sharing a quick example how?