17204: Fix misleading log message on 304 Not Modified response.

Arvados-DCO-1.1-Signed-off-by: Tom Clegg <tom@curii.com>

diff --git a/services/keep-web/handler.go b/services/keep-web/handler.go
index 4ea2fa2f6dea89af1b3a744b09a2da6d36e61169..94b59ebd41ea843d80cf32fade7e5dd6168a225e 100644 (file)
--- 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 5291efeb822a4a2fe22af022cf15208d0ee1ba7f..9252bd82d7e15cb86424106c1c76a5009061189f 100644 (file)
--- 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)