bootcfg/http: Add structured info/debug logging

* Add info logs for errors matching machine groups
or resolving profiles, or supported templates
* Add debug logs with successful match info

bootcfg/http/cloud.go

@@ -7,6 +7,7 @@ import (
 	"strings"
 	"time"
 
+	"github.com/Sirupsen/logrus"
 	cloudinit "github.com/coreos/coreos-cloudinit/config"
 	"golang.org/x/net/context"
 
@@ -24,21 +25,44 @@ type CloudConfig struct {
 func (s *Server) cloudHandler(core server.Server) ContextHandler {
 	fn := func(ctx context.Context, w http.ResponseWriter, req *http.Request) {
 		group, err := groupFromContext(ctx)
-		if err != nil || group.Profile == "" {
+		if err != nil {
+			s.logger.WithFields(logrus.Fields{
+				"labels": labelsFromRequest(nil, req),
+			}).Infof("No matching group")
 			http.NotFound(w, req)
 			return
 		}
+
 		profile, err := core.ProfileGet(ctx, &pb.ProfileGetRequest{Id: group.Profile})
-		if err != nil || profile.CloudId == "" {
+		if err != nil {
+			s.logger.WithFields(logrus.Fields{
+				"labels":     labelsFromRequest(nil, req),
+				"group":      group.Id,
+				"group_name": group.Name,
+			}).Infof("No profile named: %s", group.Profile)
 			http.NotFound(w, req)
 			return
 		}
+
 		contents, err := core.CloudGet(ctx, profile.CloudId)
 		if err != nil {
+			s.logger.WithFields(logrus.Fields{
+				"labels":     labelsFromRequest(nil, req),
+				"group":      group.Id,
+				"group_name": group.Name,
+				"profile":    group.Profile,
+			}).Infof("No cloud-config template named: %s", profile.CloudId)
 			http.NotFound(w, req)
 			return
 		}
 
+		// match was successful
+		s.logger.WithFields(logrus.Fields{
+			"labels":  labelsFromRequest(nil, req),
+			"group":   group.Id,
+			"profile": profile.Id,
+		}).Debug("Matched a cloud-config template")
+
 		// collect data for rendering
 		data := make(map[string]interface{})
 		if group.Metadata != nil {

bootcfg/http/generic.go

@@ -7,6 +7,7 @@ import (
 	"strings"
 	"time"
 
+	"github.com/Sirupsen/logrus"
 	"golang.org/x/net/context"
 
 	"github.com/coreos/coreos-baremetal/bootcfg/server"
@@ -18,21 +19,42 @@ import (
 func (s *Server) genericHandler(core server.Server) ContextHandler {
 	fn := func(ctx context.Context, w http.ResponseWriter, req *http.Request) {
 		group, err := groupFromContext(ctx)
-		if err != nil || group.Profile == "" {
+		if err != nil {
+			s.logger.WithFields(logrus.Fields{
+				"labels": labelsFromRequest(nil, req),
+			}).Infof("No matching group")
 			http.NotFound(w, req)
 			return
 		}
 		profile, err := core.ProfileGet(ctx, &pb.ProfileGetRequest{Id: group.Profile})
-		if err != nil || profile.GenericId == "" {
+		if err != nil {
+			s.logger.WithFields(logrus.Fields{
+				"labels":     labelsFromRequest(nil, req),
+				"group":      group.Id,
+				"group_name": group.Name,
+			}).Infof("No profile named: %s", group.Profile)
 			http.NotFound(w, req)
 			return
 		}
 		contents, err := core.GenericGet(ctx, profile.GenericId)
 		if err != nil {
+			s.logger.WithFields(logrus.Fields{
+				"labels":     labelsFromRequest(nil, req),
+				"group":      group.Id,
+				"group_name": group.Name,
+				"profile":    group.Profile,
+			}).Infof("No generic template named: %s", profile.GenericId)
 			http.NotFound(w, req)
 			return
 		}
 
+		// match was successful
+		s.logger.WithFields(logrus.Fields{
+			"labels":  labelsFromRequest(nil, req),
+			"group":   group.Id,
+			"profile": profile.Id,
+		}).Debug("Matched a generic template")
+
 		// collect data for rendering
 		data := make(map[string]interface{})
 		if group.Metadata != nil {

bootcfg/http/grub.go

@@ -5,6 +5,7 @@ import (
 	"net/http"
 	"text/template"
 
+	"github.com/Sirupsen/logrus"
 	"golang.org/x/net/context"
 )
 
@@ -24,9 +25,19 @@ func (s *Server) grubHandler() ContextHandler {
 	fn := func(ctx context.Context, w http.ResponseWriter, req *http.Request) {
 		profile, err := profileFromContext(ctx)
 		if err != nil {
+			s.logger.WithFields(logrus.Fields{
+				"labels": labelsFromRequest(nil, req),
+			}).Infof("No matching profile")
 			http.NotFound(w, req)
 			return
 		}
+
+		// match was successful
+		s.logger.WithFields(logrus.Fields{
+			"labels":  labelsFromRequest(nil, req),
+			"profile": profile.Id,
+		}).Debug("Matched a GRUB config")
+
 		var buf bytes.Buffer
 		err = grubTemplate.Execute(&buf, profile.Boot)
 		if err != nil {

bootcfg/http/handlers.go

@@ -39,7 +39,7 @@ func versionHandler() http.Handler {
 // logRequest logs HTTP requests.
 func (s *Server) logRequest(next http.Handler) http.Handler {
 	fn := func(w http.ResponseWriter, req *http.Request) {
-		s.logger.Debugf("HTTP %s %v", req.Method, req.URL)
+		s.logger.Infof("HTTP %s %v", req.Method, req.URL)
 		next.ServeHTTP(w, req)
 	}
 	return http.HandlerFunc(fn)

bootcfg/http/http.go

@@ -60,8 +60,11 @@ func labelsFromRequest(logger *logrus.Logger, req *http.Request) map[string]stri
 			if hw, err := parseMAC(values.Get(key)); err == nil {
 				labels[key] = hw.String()
 			} else {
-				// invalid MAC arguments may be common
-				logger.Debugf("error parsing MAC address: %s", err)
+				if logger != nil {
+					logger.WithFields(logrus.Fields{
+						"mac": values.Get(key),
+					}).Warningf("ignoring unparseable MAC address: %v", err)
+				}
 			}
 		default:
 			// matchers don't use multi-value keys, drop later values

bootcfg/http/ignition.go

@@ -6,6 +6,7 @@ import (
 	"net/http"
 	"strings"
 
+	"github.com/Sirupsen/logrus"
 	fuze "github.com/coreos/fuze/config"
 	ignition "github.com/coreos/ignition/config"
 	"golang.org/x/net/context"
@@ -22,21 +23,44 @@ import (
 func (s *Server) ignitionHandler(core server.Server) ContextHandler {
 	fn := func(ctx context.Context, w http.ResponseWriter, req *http.Request) {
 		group, err := groupFromContext(ctx)
-		if err != nil || group.Profile == "" {
+		if err != nil {
+			s.logger.WithFields(logrus.Fields{
+				"labels": labelsFromRequest(nil, req),
+			}).Infof("No matching group")
 			http.NotFound(w, req)
 			return
 		}
+
 		profile, err := core.ProfileGet(ctx, &pb.ProfileGetRequest{Id: group.Profile})
-		if err != nil || profile.IgnitionId == "" {
+		if err != nil {
+			s.logger.WithFields(logrus.Fields{
+				"labels":     labelsFromRequest(nil, req),
+				"group":      group.Id,
+				"group_name": group.Name,
+			}).Infof("No profile named: %s", group.Profile)
 			http.NotFound(w, req)
 			return
 		}
+
 		contents, err := core.IgnitionGet(ctx, profile.IgnitionId)
 		if err != nil {
+			s.logger.WithFields(logrus.Fields{
+				"labels":     labelsFromRequest(nil, req),
+				"group":      group.Id,
+				"group_name": group.Name,
+				"profile":    group.Profile,
+			}).Infof("No Ignition or Fuze template named: %s", profile.IgnitionId)
 			http.NotFound(w, req)
 			return
 		}
 
+		// match was successful
+		s.logger.WithFields(logrus.Fields{
+			"labels":  labelsFromRequest(nil, req),
+			"group":   group.Id,
+			"profile": profile.Id,
+		}).Debug("Matched an Ignition or Fuze template")
+
 		// Skip rendering if raw Ignition JSON is provided
 		if isIgnition(profile.IgnitionId) {
 			_, err := ignition.Parse([]byte(contents))
@@ -49,7 +73,7 @@ func (s *Server) ignitionHandler(core server.Server) ContextHandler {
 
 		// Fuze Config template
 
-		// collect data for rendering Ignition Config
+		// collect data for rendering
 		data := make(map[string]interface{})
 		if group.Metadata != nil {
 			err = json.Unmarshal(group.Metadata, &data)

bootcfg/http/ipxe.go

@@ -6,6 +6,7 @@ import (
 	"net/http"
 	"text/template"
 
+	"github.com/Sirupsen/logrus"
 	"golang.org/x/net/context"
 )
 
@@ -34,9 +35,19 @@ func (s *Server) ipxeHandler() ContextHandler {
 	fn := func(ctx context.Context, w http.ResponseWriter, req *http.Request) {
 		profile, err := profileFromContext(ctx)
 		if err != nil {
+			s.logger.WithFields(logrus.Fields{
+				"labels": labelsFromRequest(nil, req),
+			}).Infof("No matching profile")
 			http.NotFound(w, req)
 			return
 		}
+
+		// match was successful
+		s.logger.WithFields(logrus.Fields{
+			"labels":  labelsFromRequest(nil, req),
+			"profile": profile.Id,
+		}).Debug("Matched an iPXE config")
+
 		var buf bytes.Buffer
 		err = ipxeTemplate.Execute(&buf, profile.Boot)
 		if err != nil {

bootcfg/http/metadata.go

@@ -6,6 +6,7 @@ import (
 	"net/http"
 	"strings"
 
+	"github.com/Sirupsen/logrus"
 	"golang.org/x/net/context"
 )
 
@@ -15,11 +16,20 @@ func (s *Server) metadataHandler() ContextHandler {
 	fn := func(ctx context.Context, w http.ResponseWriter, req *http.Request) {
 		group, err := groupFromContext(ctx)
 		if err != nil {
+			s.logger.WithFields(logrus.Fields{
+				"labels": labelsFromRequest(nil, req),
+			}).Infof("No matching group")
 			http.NotFound(w, req)
 			return
 		}
-		w.Header().Set(contentType, plainContentType)
 
+		// match was successful
+		s.logger.WithFields(logrus.Fields{
+			"labels": labelsFromRequest(nil, req),
+			"group":  group.Id,
+		}).Debug("Matched group metadata")
+
+		// collect data for response
 		data := make(map[string]interface{})
 		if group.Metadata != nil {
 			err = json.Unmarshal(group.Metadata, &data)
@@ -33,6 +43,7 @@ func (s *Server) metadataHandler() ContextHandler {
 			data[key] = value
 		}
 
+		w.Header().Set(contentType, plainContentType)
 		for key, value := range data {
 			fmt.Fprintf(w, "%s=%v\n", strings.ToUpper(key), value)
 		}

bootcfg/http/pixiecore.go

@@ -4,6 +4,7 @@ import (
 	"net/http"
 	"path/filepath"
 
+	"github.com/Sirupsen/logrus"
 	"golang.org/x/net/context"
 
 	"github.com/coreos/coreos-baremetal/bootcfg/server"
@@ -15,23 +16,41 @@ import (
 // https://github.com/danderson/pixiecore/blob/master/README.api.md
 func (s *Server) pixiecoreHandler(core server.Server) ContextHandler {
 	fn := func(ctx context.Context, w http.ResponseWriter, req *http.Request) {
+		// pixiecore only provides a MAC address label
 		macAddr, err := parseMAC(filepath.Base(req.URL.Path))
 		if err != nil {
+			s.logger.Errorf("unparseable MAC address: %v", err)
 			http.Error(w, err.Error(), http.StatusBadRequest)
 			return
 		}
-		// pixiecore only provides MAC addresses
 		attrs := map[string]string{"mac": macAddr.String()}
+
 		group, err := core.SelectGroup(ctx, &pb.SelectGroupRequest{Labels: attrs})
 		if err != nil {
+			s.logger.WithFields(logrus.Fields{
+				"label": macAddr,
+			}).Infof("No matching group")
 			http.NotFound(w, req)
 			return
 		}
+
 		profile, err := core.ProfileGet(ctx, &pb.ProfileGetRequest{Id: group.Profile})
 		if err != nil {
+			s.logger.WithFields(logrus.Fields{
+				"label": macAddr,
+				"group": group.Id,
+			}).Infof("No profile named: %s", group.Profile)
 			http.NotFound(w, req)
 			return
 		}
+
+		// match was successful
+		s.logger.WithFields(logrus.Fields{
+			"label":   macAddr,
+			"group":   group.Id,
+			"profile": profile.Id,
+		}).Debug("Matched a Pixiecore config")
+
 		s.renderJSON(w, profile.Boot)
 	}
 	return ContextHandlerFunc(fn)

bootcfg/http/pixiecore_test.go

@@ -19,7 +19,8 @@ func TestPixiecoreHandler(t *testing.T) {
 		Groups:   map[string]*storagepb.Group{testGroupWithMAC.Id: testGroupWithMAC},
 		Profiles: map[string]*storagepb.Profile{testGroupWithMAC.Profile: fake.Profile},
 	}
-	srv := NewServer(&Config{})
+	logger, _ := logtest.NewNullLogger()
+	srv := NewServer(&Config{Logger: logger})
 	c := server.NewServer(&server.Config{Store: store})
 	h := srv.pixiecoreHandler(c)
 	w := httptest.NewRecorder()