Repository: buchgr/bazel-remote
Pull request #116 (2019-10-30 11:00:22)

print all logs with UTC timestamps
The cache accessLogger and errorLoggers use specific flags to specify
the time format and timezone to use (UTC). However, stray log.Printf
etc calls during startup did not use the same settings, and defaulted
to printing times relative to the local timezone.


Patch:
diff --git a/cache/disk/disk.go b/cache/disk/disk.go
index c4e0feb..3c6d983 100644
--- a/cache/disk/disk.go
+++ b/cache/disk/disk.go
@@ -150,7 +150,7 @@ func (c *diskCache) loadExistingFiles() error {
 	return nil
 }
 
-func (c *diskCache) Put(kind cache.EntryKind, hash string, expectedSize int64, r io.Reader) (err error) {
+func (c *diskCache) Put(kind cache.EntryKind, hash string, expectedSize int64, r io.Reader) error {
 	c.mux.Lock()
 
 	key := cacheKey(kind, hash)
@@ -163,7 +163,7 @@ func (c *diskCache) Put(kind cache.EntryKind, hash string, expectedSize int64, r
 		if !existingItem.(*lruItem).committed {
 			c.mux.Unlock()
 			io.Copy(ioutil.Discard, r)
-			return
+			return nil
 		}
 	}
 
@@ -199,7 +199,7 @@ func (c *diskCache) Put(kind cache.EntryKind, hash string, expectedSize int64, r
 	// Download to a temporary file
 	f, err := ioutil.TempFile(c.dir, "upload")
 	if err != nil {
-		return
+		return err
 	}
 	defer func() {
 		if !shouldCommit {
@@ -214,17 +214,16 @@ func (c *diskCache) Put(kind cache.EntryKind, hash string, expectedSize int64, r
 	if kind == cache.CAS {
 		hasher := sha256.New()
 		if bytesCopied, err = io.Copy(io.MultiWriter(f, hasher), r); err != nil {
-			return
+			return err
 		}
 		actualHash := hex.EncodeToString(hasher.Sum(nil))
 		if actualHash != hash {
-			err = fmt.Errorf(
+			return fmt.Errorf(
 				"hashsums don't match. Expected %s, found %s", key, actualHash)
-			return
 		}
 	} else {
 		if bytesCopied, err = io.Copy(f, r); err != nil {
-			return
+			return err
 		}
 	}
 
@@ -237,9 +236,8 @@ func (c *diskCache) Put(kind cache.EntryKind, hash string, expectedSize int64, r
 	}
 
 	if bytesCopied != expectedSize {
-		err = fmt.Errorf(
+		return fmt.Errorf(
 			"sizes don't match. Expected %d, found %d", expectedSize, bytesCopied)
-		return err
 	}
 
 	// Rename to the final path
@@ -251,28 +249,28 @@ func (c *diskCache) Put(kind cache.EntryKind, hash string, expectedSize int64, r
 		shouldCommit = true
 	}
 
-	return
+	return err
 }
 
 func (c *diskCache) Get(kind cache.EntryKind, hash string) (rdr io.ReadCloser, sizeBytes int64, err error) {
 	if !c.Contains(kind, hash) {
-		return
+		return nil, 0, nil
 	}
 
 	blobPath := cacheFilePath(kind, c.dir, hash)
 
 	fileInfo, err := os.Stat(blobPath)
 	if err != nil {
-		return
+		return nil, 0, err
 	}
 	sizeBytes = fileInfo.Size()
 
 	rdr, err = os.Open(blobPath)
 	if err != nil {
-		return
+		return nil, 0, err
 	}
 
-	return
+	return rdr, sizeBytes, nil
 }
 
 func (c *diskCache) Contains(kind cache.EntryKind, hash string) (ok bool) {
diff --git a/cache/http/http.go b/cache/http/http.go
index 197762b..33f3ed5 100644
--- a/cache/http/http.go
+++ b/cache/http/http.go
@@ -54,6 +54,9 @@ func uploadFile(remote *http.Client, baseURL *url.URL, local cache.Cache, access
 	if err != nil {
 		return
 	}
+	io.Copy(ioutil.Discard, rsp.Body)
+	rsp.Body.Close()
+
 	logResponse(accessLogger, "PUT", rsp.StatusCode, url)
 	return
 }
diff --git a/main.go b/main.go
index f6d1a66..651a668 100644
--- a/main.go
+++ b/main.go
@@ -27,7 +27,14 @@ import (
 	"google.golang.org/grpc/credentials"
 )
 
+const (
+	logFlags = log.Ldate | log.Ltime | log.LUTC
+)
+
 func main() {
+
+	log.SetFlags(logFlags)
+
 	app := cli.NewApp()
 	app.Description = "A remote build cache for Bazel."
 	app.Usage = "A remote build cache for Bazel"
@@ -181,8 +188,8 @@ func main() {
 			return nil
 		}
 
-		accessLogger := log.New(os.Stdout, "", log.Ldate|log.Ltime|log.LUTC)
-		errorLogger := log.New(os.Stderr, "", log.Ldate|log.Ltime|log.LUTC)
+		accessLogger := log.New(os.Stdout, "", logFlags)
+		errorLogger := log.New(os.Stderr, "", logFlags)
 
 		diskCache := disk.New(c.Dir, int64(c.MaxSize)*1024*1024*1024)
 
diff --git a/server/grpc_ac.go b/server/grpc_ac.go
index 8ae1893..3dfd737 100644
--- a/server/grpc_ac.go
+++ b/server/grpc_ac.go
@@ -13,6 +13,11 @@ import (
 	"github.com/buchgr/bazel-remote/cache"
 )
 
+var (
+	errEmptyActionResult = status.Error(codes.InvalidArgument,
+		"rejecting empty ActionResult")
+)
+
 // ActionCache interface:
 
 func (s *grpcServer) GetActionResult(ctx context.Context,
@@ -57,6 +62,12 @@ func (s *grpcServer) UpdateActionResult(ctx context.Context,
 		return nil, status.Error(codes.Unknown, err.Error())
 	}
 
+	if len(data) == 0 {
+		s.accessLogger.Printf("%s %s %s", errorPrefix, req.ActionDigest.Hash,
+			errEmptyActionResult.Error())
+		return nil, errEmptyActionResult
+	}
+
 	err = s.cache.Put(cache.AC, req.ActionDigest.Hash,
 		int64(len(data)), bytes.NewReader(data))
 	if err != nil {
diff --git a/server/http.go b/server/http.go
index 2f70d03..00dac8a 100644
--- a/server/http.go
+++ b/server/http.go
@@ -196,7 +196,7 @@ func (h *httpCache) CacheHandler(w http.ResponseWriter, r *http.Request) {
 			// We need the content-length header to make sure we have enough disk space.
 			msg := fmt.Sprintf("PUT without Content-Length (key = %s)", path(kind, hash))
 			http.Error(w, msg, http.StatusBadRequest)
-			h.errorLogger.Printf("%s", msg)
+			h.errorLogger.Printf("PUT %s: %s", path(kind, hash), msg)
 			return
 		}
 
@@ -206,17 +206,25 @@ func (h *httpCache) CacheHandler(w http.ResponseWriter, r *http.Request) {
 
 			data, err := ioutil.ReadAll(rc)
 			if err != nil {
-				msg := "Failed to read request body"
-				http.Error(w, msg, http.StatusBadRequest) // find a better status
-				h.errorLogger.Printf("%s", msg)
+				msg := "failed to read request body"
+				http.Error(w, msg, http.StatusInternalServerError)
+				h.errorLogger.Printf("PUT %s: %s", path(kind, hash), msg)
+				return
+			}
+
+			if len(data) == 0 {
+				msg := "rejecting empty ActionResult"
+				http.Error(w, msg, http.StatusBadRequest)
+				h.errorLogger.Printf("PUT %s: %s", path(kind, hash), msg)
+				return
 			}
 
 			ar := &pb.ActionResult{}
 			err = proto.Unmarshal(data, ar)
 			if err != nil {
-				msg := "Put received an invalid ActionResult"
+				msg := "received an invalid ActionResult"
 				http.Error(w, msg, http.StatusBadRequest)
-				h.errorLogger.Printf("%s", msg)
+				h.errorLogger.Printf("PUT %s: %s", path(kind, hash), msg)
 				return
 			}
 


Test patch:
diff --git a/server/grpc_test.go b/server/grpc_test.go
index a65cf43..9cb00e0 100644
--- a/server/grpc_test.go
+++ b/server/grpc_test.go
@@ -185,6 +185,30 @@ func TestGrpcAc(t *testing.T) {
 		checkBadDigestErr(t, err, tc)
 	}
 
+	zeroActionResult := pb.ActionResult{}
+	zeroData, err := proto.Marshal(&zeroActionResult)
+	if err != nil {
+		t.Fatal(err)
+	}
+	if len(zeroData) != 0 {
+		t.Fatal("expected a zero-sized test blob")
+	}
+	_, zeroHash := testutils.RandomDataAndHash(0)
+	zeroDigest := pb.Digest{
+		Hash:      zeroHash,
+		SizeBytes: 0,
+	}
+	zeroReq := pb.UpdateActionResultRequest{
+		ActionDigest: &zeroDigest,
+		ActionResult: &zeroActionResult,
+	}
+	_, err = acClient.UpdateActionResult(ctx, &zeroReq)
+	s, ok = status.FromError(err)
+	if !ok || s.Code() != codes.InvalidArgument ||
+		err.Error() != errEmptyActionResult.Error() {
+		t.Fatal("expected empty ActionResult to be rejected", err)
+	}
+
 	// GetActionResultRequest again, expect cache hit.
 
 	gacrResp, err = acClient.GetActionResult(ctx, &getReq)
diff --git a/server/http_test.go b/server/http_test.go
index ec99258..250c067 100644
--- a/server/http_test.go
+++ b/server/http_test.go
@@ -212,6 +212,47 @@ func TestUploadCorruptedFile(t *testing.T) {
 	}
 }
 
+func TestUploadEmptyActionResult(t *testing.T) {
+	cacheDir := testutils.CreateTmpCacheDirs(t)
+	defer os.RemoveAll(cacheDir)
+
+	data, hash := testutils.RandomDataAndHash(0)
+
+	r, err := http.NewRequest("PUT", "/ac/"+hash, bytes.NewReader(data))
+	if err != nil {
+		t.Error(err)
+	}
+
+	c := disk.New(cacheDir, 2048)
+	validate := true
+	h := NewHTTPCache(c, testutils.NewSilentLogger(), testutils.NewSilentLogger(), validate)
+	rr := httptest.NewRecorder()
+	handler := http.HandlerFunc(h.CacheHandler)
+	handler.ServeHTTP(rr, r)
+
+	if status := rr.Code; status != http.StatusBadRequest {
+		t.Error("Handler returned wrong status code",
+			"expected ", http.StatusBadRequest,
+			"got ", status)
+	}
+
+	// Check that no file was saved in the cache
+	f, err := os.Open(cacheDir)
+	defer f.Close()
+	if err != nil {
+		t.Fatal(err)
+	}
+	entries, err := f.Readdir(-1)
+	if err != nil {
+		t.Fatal(err)
+	}
+	for _, fileEntry := range entries {
+		if !fileEntry.IsDir() {
+			t.Error("Unexpected file in the cache ", fileEntry.Name())
+		}
+	}
+}
+
 func TestStatusPage(t *testing.T) {
 	cacheDir := testutils.CreateTmpCacheDirs(t)
 	defer os.RemoveAll(cacheDir)