Http2 stream closed / connection reset / context canceled

mdl · March 29, 2021, 10:05am

Thank you so much for restic!

Recently I started using rclone with restic and Jottacloud. Tested it for about a month with version and no issues.
I upgraded jottacloud to a paid account and started it using it in production.

I now get messages like copied below.

Is this an issue with rclone, jottacloud, or something else?

Also, it is unclear to me if these errors are corrected during the restic backup or not.

Can someone clarify?

Thank you

Using versions:
restic 0.12.0 compiled with go1.15.8 on linux/arm
rclone:
rclone v1.54.1

os/arch: linux/arm
go version: go1.15.8

rclone: 2021/03/17 12:59:31 ERROR : data/e5/e5f8f74c…: Post request put error: Post “https://060-up.jotta.cloud/files/v1/upload/eyJ0…”: write tcp 192.168.254.74:36680->185.179.128.29:443: write: connection reset by peer

Save(<data/e5f8f74c10>) returned error, retrying after 720.254544ms: server response unexpected: 500 Internal Server Error (500)

rclone: 2021/03/17 13:14:11 ERROR : data/e6/e6d1…: Post request put error: HTTP error 500 (500 Server Error) returned body: “{“code”:500,“message”:null,“cause”:”",“error_id”:“UndeclaredThrowableException”,“x-id”:“775077916577”}"

rclone: 2021/03/19 11:34:56 ERROR : index/372…: Didn’t finish writing GET request (wrote 61838/700620 bytes): context canceled
Load(<index/3721797015>, 0, 0) returned error, retrying after 873.42004ms: open /data/home/upback/restic/cache/66266…: permission denied

rclone: 2021/03/29 03:03:41 ERROR : index/37217970158…: Didn’t finish writing GET request (wrote 0/700620 bytes): http2: stream closed

764287 · April 3, 2021, 7:48am

You are seeing different errors and it’s hard to tell what has happened. Please run restic check or restic check --read-data if possible.

mdl · April 5, 2021, 1:06pm

Thank you for your reply.
A check gave no errors, will now try a check with read-data.

But please note, that these errors (Http2 stream closed / connection reset / context canceled) I get every time a run a backup to jottacload.

mdl · April 5, 2021, 2:37pm

Well, the check with read-data is running, but already there are some (interesting?) errors:
Pack ID does not match, want 5122dad7, got e3b0c442
Pack ID does not match, want 6b8bdbda, got e3b0c442
Pack ID does not match, want 11c010c8, got e3b0c442
Pack ID does not match, want 51f09a6b, got e3b0c442

each time a message in front of that line like this:
rclone: 2021/04/05 16:35:01 ERROR : data/ec/ec0ebc4e127a3b5491e81e8d9924e5e23b37ce5fbcd9eaa65e4181cccb6e066f: Didn’t finish writing GET request (wrote 0/5398597 bytes): unexpected EOF

Note that the value that restic got when the error pops up, is the same: e3b0c442

That value is mentioned also several times in this thread:

But I really don’t know if that is coincidence or not.

These are the versions of restic and rclone I am running:
2021-04-05 13:50:01 Restic version:
restic 0.12.0 compiled with go1.15.8 on linux/arm
2021-04-05 13:50:01 Rclone version:
rclone v1.55.0

os/type: linux
os/arch: arm
go/version: go1.16.2
go/linking: static
go/tags: cmount

Does this mean that my backup is no good?
And, how can one correct this?

Thank you so much for your help!

mdl · April 7, 2021, 9:56am

Hello @764287 and thank you for your reply.

The check gave no errors, a check with --read-data did.
41 lines like this:
rclone: 2021/04/05 16:56:32 ERROR : data/d2/d2d5a4a01ee936cb6d85983f35d94d78e0e4bcbb04e50dea02d3ba2c08372460: Didn't finish writing GET request (wrote 0/5554234 bytes): unexpected EOF

25 lines like this:
Load(<data/d1260fbc49>, 0, 0) returned error, retrying after 656.819981ms: <data/d1260fbc49> does not exist

And 23 lines like this:
Pack ID does not match, want aaff8c01, got e3b0c442

All 23 Pack ID that didn’t matched, all returned the value e3b0c442. Is that coincidence?

The thread I mentioned above suggest that this might be a bug in http2/go, which should be fixed in restic version 12. I am running version 12:
2021-04-05 15:19:01 Restic version:
restic 0.12.0 compiled with go1.15.8 on linux/arm
2021-04-05 15:19:01 Rclone version:
rclone v1.55.0
- os/type: linux
- os/arch: arm
- go/version: go1.16.2
- go/linking: static
- go/tags: cmount

Can some kind person tell what the problem is?
Thank you so much!

mdl · April 7, 2021, 1:17pm

The message Pack ID does not match, means that the sha256 checksum of the data of that file is not the same as the filename, am I correct?

So I downloaded a few of those pack id manually from the backend (jottacloud) and run a checksum on it. The checksum perfectly matches the filename.

Why is restic complaining about the Pack ID does not match? Is this because of an error during the download (the Didn’t finish writing GET request)?

Thank you.

mdl · April 14, 2021, 9:03am

I was curious if these errors had something to do with restic/rclone communicating using stdio, so I did set up a rclone rest server on a local port. The kind of errors remains the same. Some of them now are slightly different, perhaps this helps debugging.

2021/04/14 10:12:06 ERROR : restic/nas3/index/37217970158b2d52cc85a71181c2568fe9db9a8fd950d5e49d60af7b0be737b0: Didn’t finish writing GET request (wrote 15680/700620 bytes): write tcp 127.0.0.1:8088->127.0.0.1:54818: write: connection reset by peer

(127.0.01:8088 is where the rclone rest server is)

Any pointers are still welcome.
Thank you.

764287 · April 15, 2021, 7:35am

Sorry, but I have no idea what might cause this. It looks like a bug to me. Maybe @ncw has an idea what is goin on?

mdl · May 2, 2021, 10:24am

I am still struggling with this. I did run a check --read-data a several times, and these are my findings:

Some Pack IDs do not match. On each run these are different Pack IDs, so a pack that doesn’t match on run x can be good on run y and the other way around.
When a pack id does not match, it always has the value e3b0c442, p.e.: Pack ID does not match, want 84f8cecc, got e3b0c442
A “pack id does not match” failure is always preceded with a rclone error “Didn’t finish writing GET request (wrote 0/xxx bytes): unexpected EOF” where xxx is a different number. The bytes written however is always 0.
During a check --read-data, there are also some rclone errors that are the same, but do have a number > 0 of written bytes, but lower then xxx. These kind of errors do not result in a pack id error.

Any help is still very welcome. Thank you.

MichaelEischer · May 9, 2021, 7:09pm

e3b0c442 or the full e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855 (sha256 of an empty string) hash means that the file is empty. The GET errors make it likely that it’s just the download that failed.

From what I can tell, it looks like the download failed, but restic nevertheless got the information / interpreted it such that the download was successful. The error message originates here:

github.com

rclone/rclone/blob/732bc08ceda0d6a4432d512277b77090b8ae3b79/lib/http/serve/serve.go#L88


	tr := accounting.Stats(r.Context()).NewTransfer(o)
	defer func() {
		tr.Done(r.Context(), err)
	}()
	in := tr.Account(r.Context(), file) // account the transfer (no buffering)


	w.WriteHeader(code)


	n, err := io.Copy(w, in)
	if err != nil {
		fs.Errorf(o, "Didn't finish writing GET request (wrote %d/%d bytes): %v", n, size, err)
		return
	}
}

As the error message contains a proper file size, restic should be able to tell that 0 bytes are less than the expected xxx bytes and interpret that as an error. After some digging through the go library, it looks like the http client ignores the content-length sent by the server when no data was returned. I’ve opened an issue in the golang bugtracker: net/http: No error with http2 client on empty reply body and content-length != 0 · Issue #46071 · golang/go · GitHub

mdl · May 9, 2021, 7:39pm

Wow, thank you very much @MichaelEischer for you debugging. And on top of that opening an issue at golang! Let’s hope the golang team can solve this.

Once again a big thank you.