Bug #12247: [keepproxy] Fix misleading log message when GET response is interrupted - Arvados

Actions

Copy link

Bug #12247

closed

[keepproxy] Fix misleading log message when GET response is interrupted

Added by Tom Clegg over 7 years ago. Updated about 7 years ago.

Status:

Resolved

Priority:

Normal

Assigned To:

Tom Clegg

Category:

Keep

Target version:

2017-09-27 Sprint

Start date:

09/13/2017

Due date:

% Done:

100%

Estimated time:

(Total: 0.00 h)

Story points:

Description

Reported on mailing list:

Sep 13 11:21:12 arvados keepproxy: 2017/09/13 11:21:12 128.248.171.19,172.17.0.231:52236 GET /fe194b0a4576d5c8d9d0a2055b132b60+67108864+Ab7cbd46f674287a7e906d009c18227475a83edbb@59cbcfe9 200 67108864 34647446 http://arvados-keep01.cri.local:25107/fe194b0a4576d5c8d9d0a2055b132b60+67108864+Ab7cbd46f674287a7e906d009c18227475a83edbb@59cbcfe9 Reader failed checksum
Sep 13 11:21:29 arvados keepproxy: 2017/09/13 11:21:29 128.248.171.19,172.17.0.231:51688 GET /fe194b0a4576d5c8d9d0a2055b132b60+67108864+Ab7cbd46f674287a7e906d009c18227475a83edbb@59cbcfe9 200 67108864 30612102 http://arvados-keep01.cri.local:25107/fe194b0a4576d5c8d9d0a2055b132b60+67108864+Ab7cbd46f674287a7e906d009c18227475a83edbb@59cbcfe9 Reader failed checksum
Sep 13 11:21:44 arvados keepproxy: 2017/09/13 11:21:44 128.248.171.19,172.17.0.231:50472 GET /fe194b0a4576d5c8d9d0a2055b132b60+67108864+Ab7cbd46f674287a7e906d009c18227475a83edbb@59cbcfe9 200 67108864 34956478 http://arvados-keep01.cri.local:25107/fe194b0a4576d5c8d9d0a2055b132b60+67108864+Ab7cbd46f674287a7e906d009c18227475a83edbb@59cbcfe9 Reader failed checksum
Sep 13 11:22:00 arvados keepproxy: 2017/09/13 11:22:00 128.248.171.19,172.17.0.231:52286 GET /fe194b0a4576d5c8d9d0a2055b132b60+67108864+Ab7cbd46f674287a7e906d009c18227475a83edbb@59cbcfe9 200 67108864 63292254 http://arvados-keep01.cri.local:25107/fe194b0a4576d5c8d9d0a2055b132b60+67108864+Ab7cbd46f674287a7e906d009c18227475a83edbb@59cbcfe9 Reader failed checksum

The corresponding keepstore logs indicated everything was fine.

Suspect the following code in source:sdk/go/keepclient/hashcheck.go:

func (this HashCheckingReader) WriteTo(dest io.Writer) (written int64, err error) {
    if writeto, ok := this.Reader.(io.WriterTo); ok {
        written, err = writeto.WriteTo(io.MultiWriter(dest, this.Hash))
    } else {
        written, err = io.Copy(io.MultiWriter(dest, this.Hash), this.Reader)
    }

    sum := this.Hash.Sum(make([]byte, 0, this.Hash.Size()))

    if fmt.Sprintf("%x", sum) != this.Check {
        err = BadChecksum
    }



	If io.Copy returned a non-nil error, then we should return that error and skip the hash check, like we do in Read().


	I expect the resulting log message will be something like "write to closed socket", which would be a much better clue that the problem (if any) is just about sending the response to this particular request, and there's no reason to suspect data corruption.

Subtasks 1 (0 open — 1 closed)

Actions

Copy link

Updated by Tom Clegg over 7 years ago

Reproduced with curl on a dev cluster:

curl -H 'Authorization: OAuth2 [...]' 'http://localhost:9100/700c896930bd070fe7c8fa7344393bbd+1624300+A0a49f7074eb95caf1aeede24dfab1dbc79f598dc@59cbd944' | head -c1

↓

2017-09-13_17:02:36.08291 2017/09/13 17:02:36 [::1]:59214 GET /700c896930bd070fe7c8fa7344393bbd+1624300+A0a49f7074eb95caf1aeede24dfab1dbc79f598dc@59cbd944 200 1624300 36743 http://keep0.4xphq.arvadosapi.com:25107/700c896930bd070fe7c8fa7344393bbd+1624300+A0a49f7074eb95caf1aeede24dfab1dbc79f598dc@59cbd944 Reader failed checksum

Actions

Copy link