[ARVADOS] created: 2.1.0-718-g17a35d4e6

[Git user]

        at  17a35d4e667e2c38b5c00c174bd9a76e784ebaef (commit)


commit 17a35d4e667e2c38b5c00c174bd9a76e784ebaef
Author: Tom Clegg <tom at curii.com>
Date:   Tue Apr 20 19:43:57 2021 -0400

    17204: Fix misleading log message on 304 Not Modified response.
    
    Arvados-DCO-1.1-Signed-off-by: Tom Clegg <tom at curii.com>

diff --git a/services/keep-web/handler.go b/services/keep-web/handler.go
index 4ea2fa2f6..94b59ebd4 100644
--- a/services/keep-web/handler.go
+++ b/services/keep-web/handler.go
@@ -485,13 +485,18 @@ func (h *handler) ServeHTTP(wOrig http.ResponseWriter, r *http.Request) {
 	}
 
 	openPath := "/" + strings.Join(targetPath, "/")
-	if f, err := fs.Open(openPath); os.IsNotExist(err) {
+	f, err := fs.Open(openPath)
+	if os.IsNotExist(err) {
 		// Requested non-existent path
 		http.Error(w, notFoundMessage, http.StatusNotFound)
+		return
 	} else if err != nil {
 		// Some other (unexpected) error
 		http.Error(w, "open: "+err.Error(), http.StatusInternalServerError)
-	} else if stat, err := f.Stat(); err != nil {
+		return
+	}
+	defer f.Close()
+	if stat, err := f.Stat(); err != nil {
 		// Can't get Size/IsDir (shouldn't happen with a collectionFS!)
 		http.Error(w, "stat: "+err.Error(), http.StatusInternalServerError)
 	} else if stat.IsDir() && !strings.HasSuffix(r.URL.Path, "/") {
@@ -504,15 +509,14 @@ func (h *handler) ServeHTTP(wOrig http.ResponseWriter, r *http.Request) {
 		h.serveDirectory(w, r, collection.Name, fs, openPath, true)
 	} else {
 		http.ServeContent(w, r, basename, stat.ModTime(), f)
-		if wrote := int64(w.WroteBodyBytes()); wrote != stat.Size() && r.Header.Get("Range") == "" {
+		if wrote := int64(w.WroteBodyBytes()); wrote != stat.Size() && w.WroteStatus() == http.StatusOK {
 			// If we wrote fewer bytes than expected, it's
 			// too late to change the real response code
 			// or send an error message to the client, but
 			// at least we can try to put some useful
 			// debugging info in the logs.
 			n, err := f.Read(make([]byte, 1024))
-			ctxlog.FromContext(r.Context()).Errorf("stat.Size()==%d but only wrote %d bytes; read(1024) returns %d, %s", stat.Size(), wrote, n, err)
-
+			ctxlog.FromContext(r.Context()).Errorf("stat.Size()==%d but only wrote %d bytes; read(1024) returns %d, %v", stat.Size(), wrote, n, err)
 		}
 	}
 }
diff --git a/services/keep-web/handler_test.go b/services/keep-web/handler_test.go
index 5291efeb8..9252bd82d 100644
--- a/services/keep-web/handler_test.go
+++ b/services/keep-web/handler_test.go
@@ -6,6 +6,7 @@ package main
 
 import (
 	"bytes"
+	"context"
 	"fmt"
 	"html"
 	"io/ioutil"
@@ -16,6 +17,7 @@ import (
 	"path/filepath"
 	"regexp"
 	"strings"
+	"time"
 
 	"git.arvados.org/arvados.git/lib/config"
 	"git.arvados.org/arvados.git/sdk/go/arvados"
@@ -24,6 +26,7 @@ import (
 	"git.arvados.org/arvados.git/sdk/go/auth"
 	"git.arvados.org/arvados.git/sdk/go/ctxlog"
 	"git.arvados.org/arvados.git/sdk/go/keepclient"
+	"github.com/sirupsen/logrus"
 	check "gopkg.in/check.v1"
 )
 
@@ -72,6 +75,64 @@ func (s *UnitSuite) TestCORSPreflight(c *check.C) {
 	c.Check(resp.Code, check.Equals, http.StatusMethodNotAllowed)
 }
 
+func (s *UnitSuite) TestEmptyResponse(c *check.C) {
+	for _, trial := range []struct {
+		dataExists    bool
+		sendIMSHeader bool
+		expectStatus  int
+		logRegexp     string
+	}{
+		// If we return no content due to a Keep read error,
+		// we should emit a log message.
+		{false, false, http.StatusOK, `(?ms).*only wrote 0 bytes.*`},
+
+		// If we return no content because the client sent an
+		// If-Modified-Since header, our response should be
+		// 304, and we should not emit a log message.
+		{true, true, http.StatusNotModified, ``},
+	} {
+		c.Logf("trial: %+v", trial)
+		arvadostest.StartKeep(2, true)
+		if trial.dataExists {
+			arv, err := arvadosclient.MakeArvadosClient()
+			c.Assert(err, check.IsNil)
+			arv.ApiToken = arvadostest.ActiveToken
+			kc, err := keepclient.MakeKeepClient(arv)
+			c.Assert(err, check.IsNil)
+			_, _, err = kc.PutB([]byte("foo"))
+			c.Assert(err, check.IsNil)
+		}
+
+		h := handler{Config: newConfig(s.Config)}
+		u := mustParseURL("http://" + arvadostest.FooCollection + ".keep-web.example/foo")
+		req := &http.Request{
+			Method:     "GET",
+			Host:       u.Host,
+			URL:        u,
+			RequestURI: u.RequestURI(),
+			Header: http.Header{
+				"Authorization": {"Bearer " + arvadostest.ActiveToken},
+			},
+		}
+		if trial.sendIMSHeader {
+			req.Header.Set("If-Modified-Since", strings.Replace(time.Now().UTC().Format(time.RFC1123), "UTC", "GMT", -1))
+		}
+
+		var logbuf bytes.Buffer
+		logger := logrus.New()
+		logger.Out = &logbuf
+		req = req.WithContext(ctxlog.Context(context.Background(), logger))
+
+		resp := httptest.NewRecorder()
+		h.ServeHTTP(resp, req)
+		c.Check(resp.Code, check.Equals, trial.expectStatus)
+		c.Check(resp.Body.String(), check.Equals, "")
+
+		c.Log(logbuf.String())
+		c.Check(logbuf.String(), check.Matches, trial.logRegexp)
+	}
+}
+
 func (s *UnitSuite) TestInvalidUUID(c *check.C) {
 	bogusID := strings.Replace(arvadostest.FooCollectionPDH, "+", "-", 1) + "-"
 	token := arvadostest.ActiveToken
@@ -237,7 +298,6 @@ func (s *IntegrationSuite) doVhostRequestsWithHostPath(c *check.C, authz authori
 		if tok == arvadostest.ActiveToken {
 			c.Check(code, check.Equals, http.StatusOK)
 			c.Check(body, check.Equals, "foo")
-
 		} else {
 			c.Check(code >= 400, check.Equals, true)
 			c.Check(code < 500, check.Equals, true)

-----------------------------------------------------------------------


hooks/post-receive
--