refactor(server): Convert existing log entries to structured format

This rewrites all existing log statements into the structured logrus
format. For consistency, all errors are always logged separately from
the primary message in a field called `error`.

Only the "info", "error" and "warn" severities are used.

7 files changed, 243 insertions, 54 deletions

diff --git a/tools/nixery/server/builder/archive.go b/tools/nixery/server/builder/archive.go
index 6a2bd8e4b0..63ea9c7381 100644
--- a/tools/nixery/server/builder/archive.go
+++ b/tools/nixery/server/builder/archive.go
@@ -14,7 +14,6 @@ import (
 	"path/filepath"
 
 	"github.com/google/nixery/server/layers"
-	log "github.com/sirupsen/logrus"
 )
 
 // Create a new tarball from each of the paths in the list and write the tarball
@@ -33,7 +32,6 @@ func tarStorePaths(l *layers.Layer, w io.Writer) error {
 		return err
 	}
 
-	log.Printf("Created layer for '%s'\n", l.Hash())
 	return nil
 }
 
diff --git a/tools/nixery/server/builder/builder.go b/tools/nixery/server/builder/builder.go
index b675da0f77..14696f58a8 100644
--- a/tools/nixery/server/builder/builder.go
+++ b/tools/nixery/server/builder/builder.go
@@ -143,14 +143,17 @@ func convenienceNames(packages []string) []string {
 
 // logNix logs each output line from Nix. It runs in a goroutine per
 // output channel that should be live-logged.
-func logNix(name string, r io.ReadCloser) {
+func logNix(image, cmd string, r io.ReadCloser) {
 	scanner := bufio.NewScanner(r)
 	for scanner.Scan() {
-		log.Printf("\x1b[31m[nix - %s]\x1b[39m %s\n", name, scanner.Text())
+		log.WithFields(log.Fields{
+			"image": image,
+			"cmd":   cmd,
+		}).Info("[nix] " + scanner.Text())
 	}
 }
 
-func callNix(program string, name string, args []string) ([]byte, error) {
+func callNix(program, image string, args []string) ([]byte, error) {
 	cmd := exec.Command(program, args...)
 
 	outpipe, err := cmd.StdoutPipe()
@@ -162,24 +165,45 @@ func callNix(program string, name string, args []string) ([]byte, error) {
 	if err != nil {
 		return nil, err
 	}
-	go logNix(name, errpipe)
+	go logNix(program, image, errpipe)
 
 	if err = cmd.Start(); err != nil {
-		log.Printf("Error starting %s: %s\n", program, err)
+		log.WithFields(log.Fields{
+			"image": image,
+			"cmd":   program,
+			"error": err,
+		}).Error("error starting command")
+
 		return nil, err
 	}
-	log.Printf("Invoked Nix build (%s) for '%s'\n", program, name)
+
+	log.WithFields(log.Fields{
+		"cmd":   program,
+		"image": image,
+	}).Info("invoked Nix build")
 
 	stdout, _ := ioutil.ReadAll(outpipe)
 
 	if err = cmd.Wait(); err != nil {
-		log.Printf("%s execution error: %s\nstdout: %s\n", program, err, stdout)
+		log.WithFields(log.Fields{
+			"image":  image,
+			"cmd":    program,
+			"error":  err,
+			"stdout": stdout,
+		}).Info("Nix execution failed")
+
 		return nil, err
 	}
 
 	resultFile := strings.TrimSpace(string(stdout))
 	buildOutput, err := ioutil.ReadFile(resultFile)
 	if err != nil {
+		log.WithFields(log.Fields{
+			"image": image,
+			"file":  resultFile,
+			"error": err,
+		}).Info("failed to read Nix result file")
+
 		return nil, err
 	}
 
@@ -209,10 +233,14 @@ func prepareImage(s *State, image *Image) (*ImageResult, error) {
 
 	output, err := callNix("nixery-build-image", image.Name, args)
 	if err != nil {
-		log.Printf("failed to call nixery-build-image: %s\n", err)
+		// granular error logging is performed in callNix already
 		return nil, err
 	}
-	log.Printf("Finished image preparation for '%s' via Nix\n", image.Name)
+
+	log.WithFields(log.Fields{
+		"image": image.Name,
+		"tag":   image.Tag,
+	}).Info("finished image preparation via Nix")
 
 	var result ImageResult
 	err = json.Unmarshal(output, &result)
@@ -243,16 +271,27 @@ func prepareLayers(ctx context.Context, s *State, image *Image, result *ImageRes
 		if entry, cached := layerFromCache(ctx, s, l.Hash()); cached {
 			entries = append(entries, *entry)
 		} else {
+			lh := l.Hash()
 			lw := func(w io.Writer) error {
 				return tarStorePaths(&l, w)
 			}
 
-			entry, err := uploadHashLayer(ctx, s, l.Hash(), lw)
+			entry, err := uploadHashLayer(ctx, s, lh, lw)
 			if err != nil {
 				return nil, err
 			}
 			entry.MergeRating = l.MergeRating
 
+			var pkgs []string
+			for _, p := range l.Contents {
+				pkgs = append(pkgs, layers.PackageFromPath(p))
+			}
+
+			log.WithFields(log.Fields{
+				"layer":    lh,
+				"packages": pkgs,
+			}).Info("created image layer")
+
 			go cacheLayer(ctx, s, l.Hash(), *entry)
 			entries = append(entries, *entry)
 		}
@@ -264,7 +303,13 @@ func prepareLayers(ctx context.Context, s *State, image *Image, result *ImageRes
 	entry, err := uploadHashLayer(ctx, s, slkey, func(w io.Writer) error {
 		f, err := os.Open(result.SymlinkLayer.Path)
 		if err != nil {
-			log.Printf("failed to upload symlink layer '%s': %s\n", slkey, err)
+			log.WithFields(log.Fields{
+				"image": image.Name,
+				"tag":   image.Tag,
+				"error": err,
+				"layer": slkey,
+			}).Error("failed to upload symlink layer")
+
 			return err
 		}
 		defer f.Close()
@@ -319,7 +364,12 @@ func renameObject(ctx context.Context, s *State, old, new string) error {
 	// renaming/moving them, hence a deletion call afterwards is
 	// required.
 	if err = s.Bucket.Object(old).Delete(ctx); err != nil {
-		log.Printf("failed to delete renamed object '%s': %s\n", old, err)
+		log.WithFields(log.Fields{
+			"new":   new,
+			"old":   old,
+			"error": err,
+		}).Warn("failed to delete renamed object")
+
 		// this error should not break renaming and is not returned
 	}
 
@@ -371,12 +421,19 @@ func uploadHashLayer(ctx context.Context, s *State, key string, lw layerWriter)
 
 	err := lw(multi)
 	if err != nil {
-		log.Printf("failed to create and upload layer '%s': %s\n", key, err)
+		log.WithFields(log.Fields{
+			"layer": key,
+			"error": err,
+		}).Error("failed to create and upload layer")
+
 		return nil, err
 	}
 
 	if err = sw.Close(); err != nil {
-		log.Printf("failed to upload layer '%s' to staging: %s\n", key, err)
+		log.WithFields(log.Fields{
+			"layer": key,
+			"error": err,
+		}).Error("failed to upload layer to staging")
 	}
 
 	sha256sum := fmt.Sprintf("%x", shasum.Sum([]byte{}))
@@ -385,12 +442,21 @@ func uploadHashLayer(ctx context.Context, s *State, key string, lw layerWriter)
 	// remains is to move it to the correct location and cache it.
 	err = renameObject(ctx, s, "staging/"+key, "layers/"+sha256sum)
 	if err != nil {
-		log.Printf("failed to move layer '%s' from staging: %s\n", key, err)
+		log.WithFields(log.Fields{
+			"layer": key,
+			"error": err,
+		}).Error("failed to move layer from staging")
+
 		return nil, err
 	}
 
 	size := counter.count
-	log.Printf("Uploaded layer sha256:%s (%v bytes written)", sha256sum, size)
+
+	log.WithFields(log.Fields{
+		"layer":  key,
+		"sha256": sha256sum,
+		"size":   size,
+	}).Info("uploaded layer")
 
 	entry := manifest.Entry{
 		Digest: "sha256:" + sha256sum,
@@ -436,7 +502,12 @@ func BuildImage(ctx context.Context, s *State, image *Image) (*BuildResult, erro
 	}
 
 	if _, err = uploadHashLayer(ctx, s, c.SHA256, lw); err != nil {
-		log.Printf("failed to upload config for %s: %s\n", image.Name, err)
+		log.WithFields(log.Fields{
+			"image": image.Name,
+			"tag":   image.Tag,
+			"error": err,
+		}).Error("failed to upload config")
+
 		return nil, err
 	}
 
diff --git a/tools/nixery/server/builder/cache.go b/tools/nixery/server/builder/cache.go
index 5b6bf078b2..916de3af16 100644
--- a/tools/nixery/server/builder/cache.go
+++ b/tools/nixery/server/builder/cache.go
@@ -60,15 +60,25 @@ func (c *LocalCache) manifestFromLocalCache(key string) (json.RawMessage, bool)
 
 	f, err := os.Open(c.mdir + key)
 	if err != nil {
-		// TODO(tazjin): Once log levels are available, this
-		// might warrant a debug log.
+		// This is a debug log statement because failure to
+		// read the manifest key is currently expected if it
+		// is not cached.
+		log.WithFields(log.Fields{
+			"manifest": key,
+			"error":    err,
+		}).Debug("failed to read manifest from local cache")
+
 		return nil, false
 	}
 	defer f.Close()
 
 	m, err := ioutil.ReadAll(f)
 	if err != nil {
-		log.Printf("Failed to read manifest '%s' from local cache: %s\n", key, err)
+		log.WithFields(log.Fields{
+			"manifest": key,
+			"error":    err,
+		}).Error("failed to read manifest from local cache")
+
 		return nil, false
 	}
 
@@ -86,7 +96,10 @@ func (c *LocalCache) localCacheManifest(key string, m json.RawMessage) {
 
 	err := ioutil.WriteFile(c.mdir+key, []byte(m), 0644)
 	if err != nil {
-		log.Printf("Failed to locally cache manifest for '%s': %s\n", key, err)
+		log.WithFields(log.Fields{
+			"manifest": key,
+			"error":    err,
+		}).Error("failed to locally cache manifest")
 	}
 }
 
@@ -123,18 +136,29 @@ func manifestFromCache(ctx context.Context, s *State, key string) (json.RawMessa
 
 	r, err := obj.NewReader(ctx)
 	if err != nil {
-		log.Printf("Failed to retrieve manifest '%s' from cache: %s\n", key, err)
+		log.WithFields(log.Fields{
+			"manifest": key,
+			"error":    err,
+		}).Error("failed to retrieve manifest from bucket cache")
+
 		return nil, false
 	}
 	defer r.Close()
 
 	m, err := ioutil.ReadAll(r)
 	if err != nil {
-		log.Printf("Failed to read cached manifest for '%s': %s\n", key, err)
+		log.WithFields(log.Fields{
+			"manifest": key,
+			"error":    err,
+		}).Error("failed to read cached manifest from bucket")
+
+		return nil, false
 	}
 
 	go s.Cache.localCacheManifest(key, m)
-	log.Printf("Retrieved manifest for sha1:%s from GCS\n", key)
+	log.WithFields(log.Fields{
+		"manifest": key,
+	}).Info("retrieved manifest from GCS")
 
 	return json.RawMessage(m), true
 }
@@ -149,16 +173,27 @@ func cacheManifest(ctx context.Context, s *State, key string, m json.RawMessage)
 
 	size, err := io.Copy(w, r)
 	if err != nil {
-		log.Printf("failed to cache manifest sha1:%s: %s\n", key, err)
+		log.WithFields(log.Fields{
+			"manifest": key,
+			"error":    err,
+		}).Error("failed to cache manifest to GCS")
+
 		return
 	}
 
 	if err = w.Close(); err != nil {
-		log.Printf("failed to cache manifest sha1:%s: %s\n", key, err)
+		log.WithFields(log.Fields{
+			"manifest": key,
+			"error":    err,
+		}).Error("failed to cache manifest to GCS")
+
 		return
 	}
 
-	log.Printf("Cached manifest sha1:%s (%v bytes written)\n", key, size)
+	log.WithFields(log.Fields{
+		"manifest": key,
+		"size":     size,
+	}).Info("cached manifest to GCS")
 }
 
 // Retrieve a layer build from the cache, first checking the local
@@ -176,7 +211,11 @@ func layerFromCache(ctx context.Context, s *State, key string) (*manifest.Entry,
 
 	r, err := obj.NewReader(ctx)
 	if err != nil {
-		log.Printf("Failed to retrieve layer build '%s' from cache: %s\n", key, err)
+		log.WithFields(log.Fields{
+			"layer": key,
+			"error": err,
+		}).Error("failed to retrieve cached layer from GCS")
+
 		return nil, false
 	}
 	defer r.Close()
@@ -184,14 +223,22 @@ func layerFromCache(ctx context.Context, s *State, key string) (*manifest.Entry,
 	jb := bytes.NewBuffer([]byte{})
 	_, err = io.Copy(jb, r)
 	if err != nil {
-		log.Printf("Failed to read layer build '%s' from cache: %s\n", key, err)
+		log.WithFields(log.Fields{
+			"layer": key,
+			"error": err,
+		}).Error("failed to read cached layer from GCS")
+
 		return nil, false
 	}
 
 	var entry manifest.Entry
 	err = json.Unmarshal(jb.Bytes(), &entry)
 	if err != nil {
-		log.Printf("Failed to unmarshal layer build '%s' from cache: %s\n", key, err)
+		log.WithFields(log.Fields{
+			"layer": key,
+			"error": err,
+		}).Error("failed to unmarshal cached layer")
+
 		return nil, false
 	}
 
@@ -210,12 +257,20 @@ func cacheLayer(ctx context.Context, s *State, key string, entry manifest.Entry)
 
 	_, err := io.Copy(w, bytes.NewReader(j))
 	if err != nil {
-		log.Printf("failed to cache build '%s': %s\n", key, err)
+		log.WithFields(log.Fields{
+			"layer": key,
+			"error": err,
+		}).Error("failed to cache layer")
+
 		return
 	}
 
 	if err = w.Close(); err != nil {
-		log.Printf("failed to cache build '%s': %s\n", key, err)
+		log.WithFields(log.Fields{
+			"layer": key,
+			"error": err,
+		}).Error("failed to cache layer")
+
 		return
 	}
 }
diff --git a/tools/nixery/server/config/config.go b/tools/nixery/server/config/config.go
index abc067855a..9447975aa9 100644
--- a/tools/nixery/server/config/config.go
+++ b/tools/nixery/server/config/config.go
@@ -32,14 +32,20 @@ func signingOptsFromEnv() *storage.SignedURLOptions {
 	id := os.Getenv("GCS_SIGNING_ACCOUNT")
 
 	if path == "" || id == "" {
-		log.Println("GCS URL signing disabled")
+		log.Info("GCS URL signing disabled")
 		return nil
 	}
 
-	log.Printf("GCS URL signing enabled with account %q\n", id)
+	log.WithFields(log.Fields{
+		"account": id,
+	}).Info("GCS URL signing enabled")
+
 	k, err := ioutil.ReadFile(path)
 	if err != nil {
-		log.Fatalf("Failed to read GCS signing key: %s\n", err)
+		log.WithFields(log.Fields{
+			"file":  path,
+			"error": err,
+		}).Fatal("failed to read GCS signing key")
 	}
 
 	return &storage.SignedURLOptions{
@@ -52,7 +58,10 @@ func signingOptsFromEnv() *storage.SignedURLOptions {
 func getConfig(key, desc, def string) string {
 	value := os.Getenv(key)
 	if value == "" && def == "" {
-		log.Fatalln(desc + " must be specified")
+		log.WithFields(log.Fields{
+			"option":      key,
+			"description": desc,
+		}).Fatal("missing required configuration envvar")
 	} else if value == "" {
 		return def
 	}
diff --git a/tools/nixery/server/config/pkgsource.go b/tools/nixery/server/config/pkgsource.go
index 98719eccea..3a817f3d76 100644
--- a/tools/nixery/server/config/pkgsource.go
+++ b/tools/nixery/server/config/pkgsource.go
@@ -132,21 +132,30 @@ func (p *PkgsPath) CacheKey(pkgs []string, tag string) string {
 // specified, the Nix code will default to a recent NixOS channel.
 func pkgSourceFromEnv() (PkgSource, error) {
 	if channel := os.Getenv("NIXERY_CHANNEL"); channel != "" {
-		log.Printf("Using Nix package set from Nix channel %q\n", channel)
+		log.WithFields(log.Fields{
+			"channel": channel,
+		}).Info("using Nix package set from Nix channel or commit")
+
 		return &NixChannel{
 			channel: channel,
 		}, nil
 	}
 
 	if git := os.Getenv("NIXERY_PKGS_REPO"); git != "" {
-		log.Printf("Using Nix package set from git repository at %q\n", git)
+		log.WithFields(log.Fields{
+			"repo": git,
+		}).Info("using NIx package set from git repository")
+
 		return &GitSource{
 			repository: git,
 		}, nil
 	}
 
 	if path := os.Getenv("NIXERY_PKGS_PATH"); path != "" {
-		log.Printf("Using Nix package set from path %q\n", path)
+		log.WithFields(log.Fields{
+			"path": path,
+		}).Info("using Nix package set at local path")
+
 		return &PkgsPath{
 			path: path,
 		}, nil
diff --git a/tools/nixery/server/layers/grouping.go b/tools/nixery/server/layers/grouping.go
index 95198c90d4..1fbbf33db3 100644
--- a/tools/nixery/server/layers/grouping.go
+++ b/tools/nixery/server/layers/grouping.go
@@ -172,8 +172,14 @@ func (c *closure) ID() int64 {
 
 var nixRegexp = regexp.MustCompile(`^/nix/store/[a-z0-9]+-`)
 
+// PackageFromPath returns the name of a Nix package based on its
+// output store path.
+func PackageFromPath(path string) string {
+	return nixRegexp.ReplaceAllString(path, "")
+}
+
 func (c *closure) DOTID() string {
-	return nixRegexp.ReplaceAllString(c.Path, "")
+	return PackageFromPath(c.Path)
 }
 
 // bigOrPopular checks whether this closure should be considered for
@@ -321,7 +327,10 @@ func dominate(budget int, graph *simple.DirectedGraph) []Layer {
 	})
 
 	if len(layers) > budget {
-		log.Printf("Ideal image has %v layers, but budget is %v\n", len(layers), budget)
+		log.WithFields(log.Fields{
+			"layers": len(layers),
+			"budget": budget,
+		}).Info("ideal image exceeds layer budget")
 	}
 
 	for len(layers) > budget {
diff --git a/tools/nixery/server/main.go b/tools/nixery/server/main.go
index 06de6a96a1..babf50790f 100644
--- a/tools/nixery/server/main.go
+++ b/tools/nixery/server/main.go
@@ -68,7 +68,9 @@ var (
 // The Docker client is known to follow redirects, but this might not be true
 // for all other registry clients.
 func constructLayerUrl(cfg *config.Config, digest string) (string, error) {
-	log.Printf("Redirecting layer '%s' request to bucket '%s'\n", digest, cfg.Bucket)
+	log.WithFields(log.Fields{
+		"layer": digest,
+	}).Info("redirecting layer request to bucket")
 	object := "layers/" + digest
 
 	if cfg.Signing != nil {
@@ -90,13 +92,18 @@ func constructLayerUrl(cfg *config.Config, digest string) (string, error) {
 func prepareBucket(ctx context.Context, cfg *config.Config) *storage.BucketHandle {
 	client, err := storage.NewClient(ctx)
 	if err != nil {
-		log.Fatalln("Failed to set up Cloud Storage client:", err)
+		log.WithFields(log.Fields{
+			"error": err,
+		}).Fatal("failed to set up Cloud Storage client")
 	}
 
 	bkt := client.Bucket(cfg.Bucket)
 
 	if _, err := bkt.Attrs(ctx); err != nil {
-		log.Fatalln("Could not access configured bucket", err)
+		log.WithFields(log.Fields{
+			"error":  err,
+			"bucket": cfg.Bucket,
+		}).Fatal("could not access configured bucket")
 	}
 
 	return bkt
@@ -169,13 +176,24 @@ func (h *registryHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	if len(manifestMatches) == 3 {
 		imageName := manifestMatches[1]
 		imageTag := manifestMatches[2]
-		log.Printf("Requesting manifest for image %q at tag %q", imageName, imageTag)
+
+		log.WithFields(log.Fields{
+			"image": imageName,
+			"tag":   imageTag,
+		}).Info("requesting image manifest")
+
 		image := builder.ImageFromName(imageName, imageTag)
 		buildResult, err := builder.BuildImage(h.ctx, h.state, &image)
 
 		if err != nil {
 			writeError(w, 500, "UNKNOWN", "image build failure")
-			log.Println("Failed to build image manifest", err)
+
+			log.WithFields(log.Fields{
+				"image": imageName,
+				"tag":   imageTag,
+				"error": err,
+			}).Error("failed to build image manifest")
+
 			return
 		}
 
@@ -184,7 +202,13 @@ func (h *registryHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		if buildResult.Error == "not_found" {
 			s := fmt.Sprintf("Could not find Nix packages: %v", buildResult.Pkgs)
 			writeError(w, 404, "MANIFEST_UNKNOWN", s)
-			log.Println(s)
+
+			log.WithFields(log.Fields{
+				"image":    imageName,
+				"tag":      imageTag,
+				"packages": buildResult.Pkgs,
+			}).Error("could not find Nix packages")
+
 			return
 		}
 
@@ -205,7 +229,11 @@ func (h *registryHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		url, err := constructLayerUrl(&h.state.Cfg, digest)
 
 		if err != nil {
-			log.Printf("Failed to sign GCS URL: %s\n", err)
+			log.WithFields(log.Fields{
+				"layer": digest,
+				"error": err,
+			}).Error("failed to sign GCS URL")
+
 			writeError(w, 500, "UNKNOWN", "could not serve layer")
 			return
 		}
@@ -215,28 +243,38 @@ func (h *registryHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
-	log.Printf("Unsupported registry route: %s\n", r.RequestURI)
+	log.WithFields(log.Fields{
+		"uri": r.RequestURI,
+	}).Info("unsupported registry route")
+
 	w.WriteHeader(404)
 }
 
 func main() {
 	cfg, err := config.FromEnv()
 	if err != nil {
-		log.Fatalln("Failed to load configuration", err)
+		log.WithFields(log.Fields{
+			"error": err,
+		}).Fatal("failed to load configuration")
 	}
 
 	ctx := context.Background()
 	bucket := prepareBucket(ctx, &cfg)
 	cache, err := builder.NewCache()
 	if err != nil {
-		log.Fatalln("Failed to instantiate build cache", err)
+		log.WithFields(log.Fields{
+			"error": err,
+		}).Fatal("failed to instantiate build cache")
 	}
 
 	var pop layers.Popularity
 	if cfg.PopUrl != "" {
 		pop, err = downloadPopularity(cfg.PopUrl)
 		if err != nil {
-			log.Fatalln("Failed to fetch popularity information", err)
+			log.WithFields(log.Fields{
+				"error":  err,
+				"popURL": cfg.PopUrl,
+			}).Fatal("failed to fetch popularity information")
 		}
 	}