pixiecore: rework logging to provide less verbose, more useful logs by default.

Also adds a debug channel with the full line noise.

pixiecore/cli/apicmd.go

@@ -48,7 +48,8 @@ the Pixiecore boot API. The specification can be found at <TODO>.`,
 		s := &pixiecore.Server{
 			Booter: booter,
 			Ipxe:   Ipxe,
-			Log:    func(msg string) { fmt.Println(msg) },
+			Log:    logStdout,
+			Debug:  debugLog,
 		}
 		fmt.Println(s.Serve())
 	}}

pixiecore/cli/bootcmd.go

@@ -56,7 +56,8 @@ var bootCmd = &cobra.Command{
 		s := &pixiecore.Server{
 			Booter: booter,
 			Ipxe:   Ipxe,
-			Log:    func(msg string) { fmt.Println(msg) },
+			Log:    logStdout,
+			Debug:  debugLog,
 		}
 		fmt.Println(s.Serve())
 	},

pixiecore/cli/v1compat.go

@@ -81,7 +81,8 @@ func v1compatCLI() bool {
 		s := &pixiecore.Server{
 			Booter:   booter,
 			Ipxe:     Ipxe,
-			Log:      func(msg string) { fmt.Println(msg) },
+			Log:      logStdout,
+			Debug:    debugLog,
 			Address:  *listenAddr,
 			HTTPPort: *portHTTP,
 			DHCPPort: *portDHCP,
@@ -116,7 +117,8 @@ func v1compatCLI() bool {
 		s := &pixiecore.Server{
 			Booter:   booter,
 			Ipxe:     Ipxe,
-			Log:      func(msg string) { fmt.Println(msg) },
+			Log:      logStdout,
+			Debug:    debugLog,
 			Address:  *listenAddr,
 			HTTPPort: *portHTTP,
 			DHCPPort: *portDHCP,

pixiecore/dhcp.go

@@ -26,7 +26,7 @@ func (s *Server) serveDHCP(conn *dhcp4.Conn) {
 	for {
 		pkt, intf, err := conn.RecvDHCP()
 		if err != nil {
-			s.logf("receiving DHCP packet: %s", err)
+			s.log("DHCP", "Receiving packet: %s", err)
 			// TODO: fatal errors that return from one of the handler
 			// goroutines should plumb the error back to the
 			// coordinating goroutine, so that it can do an orderly
@@ -36,54 +36,65 @@ func (s *Server) serveDHCP(conn *dhcp4.Conn) {
 			return
 		}
 		if intf == nil {
-			s.logf("received DHCP packet with no interface information (this is a violation of dhcp4.Conn's contract)")
+			s.log("DHCP", "Received packet with no interface information (this is a violation of dhcp4.Conn's contract, please file a bug)")
 			return
 		}
 
+		if err = s.isBootDHCP(pkt); err != nil {
+			s.debug("DHCP", "Ignoring packet from %s: %s", pkt.HardwareAddr, err)
+			continue
+		}
 		mach, isIpxe, fwtype, err := s.validateDHCP(pkt)
 		if err != nil {
-			s.logf("DHCP packet from %s not usable: %s", pkt.HardwareAddr, err)
+			s.log("DHCP", "Unusable packet from %s: %s", pkt.HardwareAddr, err)
 			continue
 		}
 
 		spec, err := s.Booter.BootSpec(mach)
 		if err != nil {
-			s.logf("couldn't get bootspec for %s: %s", pkt.HardwareAddr, err)
+			s.log("DHCP", "Couldn't get bootspec for %s: %s", pkt.HardwareAddr, err)
 			continue
 		}
 		if spec == nil {
-			s.logf("booter gave no spec for %s, ignoring boot request", pkt.HardwareAddr)
+			s.debug("DHCP", "No boot spec for %s, ignoring boot request", pkt.HardwareAddr)
 			continue
 		}
 
+		s.log("DHCP", "Offering to boot %s", pkt.HardwareAddr)
+
 		// Machine should be booted.
 		serverIP, err := interfaceIP(intf)
 		if err != nil {
-			s.logf("want to boot %s on %s, but couldn't find a unicast source address on that interface: %s", pkt.HardwareAddr, intf.Name, err)
+			s.log("DHCP", "Want to boot %s on %s, but couldn't get a source address: %s", pkt.HardwareAddr, intf.Name, err)
 			continue
 		}
 
 		resp, err := s.offerDHCP(pkt, mach, serverIP, isIpxe, fwtype)
 		if err != nil {
-			s.logf("failed to construct ProxyDHCP offer for %s: %s", pkt.HardwareAddr, err)
+			s.log("DHCP", "Failed to construct ProxyDHCP offer for %s: %s", pkt.HardwareAddr, err)
 			continue
 		}
 
 		if err = conn.SendDHCP(resp, intf); err != nil {
-			s.logf("failed to send ProxyDHCP offer for %s: %s", pkt.HardwareAddr, err)
+			s.log("DHCP", "Failed to send ProxyDHCP offer for %s: %s", pkt.HardwareAddr, err)
 			continue
 		}
 	}
 }
 
-func (s *Server) validateDHCP(pkt *dhcp4.Packet) (mach Machine, isIpxe bool, fwtype Firmware, err error) {
+func (s *Server) isBootDHCP(pkt *dhcp4.Packet) error {
 	if pkt.Type != dhcp4.MsgDiscover {
-		return mach, false, 0, errors.New("not a DHCPDISCOVER packet")
+		return fmt.Errorf("packet is %s, not %s", pkt.Type, dhcp4.MsgDiscover)
 	}
 
 	if pkt.Options[93] == nil {
-		return mach, false, 0, errors.New("not a PXE boot request (missing option 93)")
+		return errors.New("not a PXE boot request (missing option 93)")
 	}
+
+	return nil
+}
+
+func (s *Server) validateDHCP(pkt *dhcp4.Packet) (mach Machine, isIpxe bool, fwtype Firmware, err error) {
 	fwt, err := pkt.Options.Uint16(93)
 	if err != nil {
 		return mach, false, 0, fmt.Errorf("malformed DHCP option 93 (required for PXE): %s", err)
@@ -218,5 +229,5 @@ func interfaceIP(intf *net.Interface) (net.IP, error) {
 		}
 	}
 
-	return nil, errors.New("no usable source address")
+	return nil, errors.New("no usable unicast address configured on interface")
 }

pixiecore/http.go

@@ -26,29 +26,55 @@ import (
 	"text/template"
 )
 
-func (s *Server) httpError(w http.ResponseWriter, r *http.Request, status int, format string, args ...interface{}) {
+func (s *Server) serveHTTP(l net.Listener) {
-	s.logHTTP(r, format, args...)
+	httpMux := http.NewServeMux()
-	http.Error(w, fmt.Sprintf(format, args...), status)
+	httpMux.HandleFunc("/_/ipxe", s.handleIpxe)
+	httpMux.HandleFunc("/_/file", s.handleFile)
+	if err := http.Serve(l, httpMux); err != nil {
+		s.log("HTTP", "%s", err)
+		// TODO: fatal errors that return from one of the handler
+		// goroutines should plumb the error back to the
+		// coordinating goroutine, so that it can do an orderly
+		// shutdown and return the error from Serve(). This "log +
+		// randomly stop a piece of pixiecore" is a terrible
+		// kludge.
+		return
+	}
 }
 
 func (s *Server) handleIpxe(w http.ResponseWriter, r *http.Request) {
-	args := r.URL.Query()
+	macStr := r.URL.Query().Get("mac")
-	mac, err := net.ParseMAC(args.Get("mac"))
+	if macStr == "" {
-	if err != nil {
+		s.debug("HTTP", "Bad request %q from %s, missing MAC address", r.URL, r.RemoteAddr)
-		s.httpError(w, r, http.StatusBadRequest, "invalid MAC address %q: %s\n", args.Get("mac"), err)
+		http.Error(w, "missing MAC address parameter", http.StatusBadRequest)
+		return
+	}
+	archStr := r.URL.Query().Get("arch")
+	if archStr == "" {
+		s.debug("HTTP", "Bad request %q from %s, missing architecture", r.URL, r.RemoteAddr)
+		http.Error(w, "missing architecture parameter", http.StatusBadRequest)
 		return
 	}
 
-	i, err := strconv.Atoi(args.Get("arch"))
+	mac, err := net.ParseMAC(macStr)
 	if err != nil {
-		s.httpError(w, r, http.StatusBadRequest, "invalid architecture %q: %s\n", args.Get("arch"), err)
+		s.debug("HTTP", "Bad request %q from %s, invalid MAC address %q (%s)", r.URL, r.RemoteAddr, macStr, err)
+		http.Error(w, "invalid MAC address", http.StatusBadRequest)
+		return
+	}
+
+	i, err := strconv.Atoi(archStr)
+	if err != nil {
+		s.debug("HTTP", "Bad request %q from %s, invalid architecture %q (%s)", r.URL, r.RemoteAddr, archStr, err)
+		http.Error(w, "invalid architecture", http.StatusBadRequest)
 		return
 	}
 	arch := Architecture(i)
 	switch arch {
 	case ArchIA32, ArchX64:
 	default:
-		s.httpError(w, r, http.StatusBadRequest, "Unknown architecture %q\n", arch)
+		s.debug("HTTP", "Bad request %q from %s, unknown architecture %q", r.URL, r.RemoteAddr, arch)
+		http.Error(w, "unknown architecture", http.StatusBadRequest)
 		return
 	}
 
@@ -58,39 +84,48 @@ func (s *Server) handleIpxe(w http.ResponseWriter, r *http.Request) {
 	}
 	spec, err := s.Booter.BootSpec(mach)
 	if err != nil {
-		// TODO: maybe don't send this error over the network?
+		s.log("HTTP", "Couldn't get a bootspec for %s (query %q from %s): %s", mac, r.URL, r.RemoteAddr, err)
-		s.logHTTP(r, "error getting bootspec for %#v: %s", mach, err)
 		http.Error(w, "couldn't get a bootspec", http.StatusInternalServerError)
 		return
 	}
 	if spec == nil {
 		// TODO: make ipxe abort netbooting so it can fall through to
 		// other boot options - unsure if that's possible.
-		s.httpError(w, r, http.StatusNotFound, "no bootspec found for %q", mach.MAC)
+		s.debug("HTTP", "No boot spec for %s (query %q from %s), ignoring boot request", mac, r.URL, r.RemoteAddr)
+		http.Error(w, "you don't netboot", http.StatusNotFound)
 		return
 	}
 	script, err := ipxeScript(spec, r.Host)
 	if err != nil {
-		s.logHTTP(r, "failed to assemble ipxe script: %s", err)
+		s.log("HTTP", "Failed to assemble ipxe script for %s (query %q from %s): %s", mac, r.URL, r.RemoteAddr, err)
-		http.Error(w, "couldn't get a bootspec", http.StatusInternalServerError)
+		http.Error(w, "couldn't get a boot script", http.StatusInternalServerError)
+		return
 	}
 
+	s.log("HTTP", "Sending ipxe boot script to %s", r.RemoteAddr)
 	w.Header().Set("Content-Type", "text/plain")
 	w.Write(script)
 }
 
 func (s *Server) handleFile(w http.ResponseWriter, r *http.Request) {
 	name := r.URL.Query().Get("name")
+	if name == "" {
+		s.debug("HTTP", "Bad request %q from %s, missing filename", r.URL, r.RemoteAddr)
+		http.Error(w, "missing filename", http.StatusBadRequest)
+	}
+
 	f, err := s.Booter.ReadBootFile(ID(name))
 	if err != nil {
-		s.logHTTP(r, "error getting requested file %q: %s", name, err)
+		s.log("HTTP", "Error getting file %q (query %q from %s)", name, r.URL, r.RemoteAddr)
 		http.Error(w, "couldn't get file", http.StatusInternalServerError)
 		return
 	}
 	defer f.Close()
 	if _, err = io.Copy(w, f); err != nil {
-		s.logHTTP(r, "copy of file %q failed: %s", name, err)
+		s.log("HTTP", "Copy of %q to %s (query %q) failed: %s", name, r.RemoteAddr, r.URL, err)
+		return
 	}
+	s.log("HTTP", "Sent file %q to %s", name, r.RemoteAddr)
 }
 
 func ipxeScript(spec *Spec, serverHost string) ([]byte, error) {

pixiecore/http_test.go

@@ -22,6 +22,7 @@ import (
 	"io/ioutil"
 	"net/http"
 	"net/http/httptest"
+	"sync"
 	"testing"
 )
 
@@ -31,6 +32,8 @@ func (b booterFunc) BootSpec(m Machine) (*Spec, error)         { return b(m) }
 func (b booterFunc) ReadBootFile(id ID) (io.ReadCloser, error) { return nil, errors.New("no") }
 func (b booterFunc) WriteBootFile(id ID, r io.Reader) error    { return errors.New("no") }
 
+var logSync sync.Mutex
+
 func TestIpxe(t *testing.T) {
 	booter := func(m Machine) (*Spec, error) {
 		return &Spec{
@@ -43,9 +46,11 @@ func TestIpxe(t *testing.T) {
 			Message: "Hello from the test!",
 		}, nil
 	}
+	log := func(subsystem, msg string) { t.Logf("[%s] %s", subsystem, msg) }
 	s := &Server{
 		Booter: booterFunc(booter),
-		Log:    func(msg string) { fmt.Println(msg) },
+		Log:    log,
+		Debug:  log,
 	}
 
 	// Successful boot
@@ -150,9 +155,11 @@ func (b readBootFile) ReadBootFile(id ID) (io.ReadCloser, error) {
 func (b readBootFile) WriteBootFile(id ID, r io.Reader) error { return errors.New("no") }
 
 func TestFile(t *testing.T) {
+	log := func(subsystem, msg string) { t.Logf("[%s] %s", subsystem, msg) }
 	s := &Server{
 		Booter: readBootFile("stuff"),
-		Log:    func(msg string) { fmt.Println(msg) },
+		Log:    log,
+		Debug:  log,
 	}
 	rr := httptest.NewRecorder()
 	req, err := http.NewRequest("GET", "/_/file?name=test", nil)

pixiecore/logging.go

@@ -15,22 +15,27 @@
 package pixiecore
 
 import (
+	"encoding/base64"
 	"fmt"
-	"net/http"
 )
 
-func (s *Server) logf(format string, args ...interface{}) {
+func (s *Server) log(subsystem, format string, args ...interface{}) {
 	if s.Log == nil {
 		return
 	}
-	s.Log(fmt.Sprintf(format, args...))
+	s.Log(subsystem, fmt.Sprintf(format, args...))
 }
 
-// logHTTP logs a message with some context about the HTTP request
+func (s *Server) debug(subsystem, format string, args ...interface{}) {
-// that caused the statement to be logged.
+	if s.Debug == nil {
-func (s *Server) logHTTP(r *http.Request, format string, args ...interface{}) {
+		return
-	if s.Log != nil {
-		pfx := fmt.Sprintf("HTTP request for %s from %s: ", r.URL, r.RemoteAddr)
-		s.logf(pfx+format, args...)
 	}
+	s.Debug(subsystem, fmt.Sprintf(format, args...))
+}
+
+func (s *Server) debugPacket(subsystem string, layer int, packet []byte) {
+	if s.Debug == nil {
+		return
+	}
+	s.Debug(subsystem, fmt.Sprintf("PKT %d %s END", layer, base64.StdEncoding.EncodeToString(packet)))
 }

pixiecore/pixiecore.go

@@ -19,7 +19,6 @@ import (
 	"fmt"
 	"io"
 	"net"
-	"net/http"
 	"strings"
 	"text/template"
 
@@ -29,7 +28,7 @@ import (
 const (
 	portDHCP = 67
 	portTFTP = 69
-	portHTTP = 81
+	portHTTP = 80
 	portPXE  = 4011
 )
 
@@ -143,11 +142,10 @@ type Server struct {
 
 	// Log receives logs on Pixiecore's operation. If nil, logging
 	// is suppressed.
-	//
+	Log func(subsystem, msg string)
-	// TODO: until Trace is better defined and plumbed through, we use
+	// Debug receives extensive logging on Pixiecore's internals. Very
-	// Log extensively, which may make it too noisy for normal
+	// useful for debugging, but very verbose.
-	// use. Need to decide what, if anything, we should do about that.
+	Debug func(subsystem, msg string)
-	Log func(msg string)
 
 	// These ports can technically be set for testing, but the
 	// protocols burned in firmware on the client side hardcode these,
@@ -155,16 +153,6 @@ type Server struct {
 	DHCPPort int
 	TFTPPort int
 	PXEPort  int
-
-	// Trace receives huge amounts of detail about what Pixiecore is
-	// doing, including raw packets it sent/received. This should be
-	// nil unless you intend to provide a bug report.
-	//
-	// TODO: figure out the format this logs in, and write a
-	// decoder. It'll likely include bits of pcap for packets
-	// received, interleaved with what bits of Pixiecore thought about
-	// them, so that you get a timeline complete with wire traffic.
-	Trace io.Writer
 }
 
 // Serve listens for machines attempting to boot, and uses Booter to
@@ -198,15 +186,19 @@ func (s *Server) Serve() error {
 		tftp.Close()
 		return err
 	}
+	http, err := net.Listen("tcp", fmt.Sprintf("%s:%d", s.Address, s.HTTPPort))
+	if err != nil {
+		dhcp.Close()
+		tftp.Close()
+		pxe.Close()
+		return err
+	}
 
 	// TODO: have something here for orderly shutdown when things go wrong.
 
 	go s.serveDHCP(dhcp)
 	go s.servePXE(pxe)
 	go s.serveTFTP(tftp)
-	http.HandleFunc("/_/ipxe", s.handleIpxe)
+	go s.serveHTTP(http)
-	http.HandleFunc("/_/file", s.handleFile)
+	select {}
-	http.ListenAndServe(fmt.Sprintf("%s:%d", s.Address, s.HTTPPort), nil)
-
-	return nil
 }

pixiecore/pxe.go

@@ -39,68 +39,64 @@ func (s *Server) servePXE(conn net.PacketConn) {
 		// shutdown and return the error from Serve(). This "log +
 		// randomly stop a piece of pixiecore" is a terrible
 		// kludge.
-		s.logf("couldn't get interface metadata on PXE PacketConn: %s", err)
+		s.log("PXE", "Couldn't get interface metadata on PXE port: %s", err)
 		return
 	}
 
 	for {
 		n, msg, addr, err := l.ReadFrom(buf)
 		if err != nil {
-			s.logf("receiving PXE packet: %s", err)
+			s.log("PXE", "Receiving packet: %s", err)
 			return
 		}
 
 		pkt, err := dhcp4.Unmarshal(buf[:n])
 		if err != nil {
-			s.logf("PXE request from %s not usable: %s", addr, err)
+			s.debug("PXE", "Packet from %s is not a DHCP packet: %s", addr, err)
 			continue
 		}
 
+		if err = s.isBootDHCP(pkt); err != nil {
+			s.debug("PXE", "Ignoring packet from %s (%s): %s", pkt.HardwareAddr, addr, err)
+		}
 		fwtype, err := s.validatePXE(pkt)
 		if err != nil {
-			s.logf("PXE request from %s not usable: %s", addr, err)
+			s.log("PXE", "Unusable packet from %s (%s): %s", pkt.HardwareAddr, addr, err)
 			continue
 		}
 
 		intf, err := net.InterfaceByIndex(msg.IfIndex)
 		if err != nil {
-			s.logf("Couldn't get information about local network interface %d: %s", msg.IfIndex, err)
+			s.log("PXE", "Couldn't get information about local network interface %d: %s", msg.IfIndex, err)
 			continue
 		}
 
 		serverIP, err := interfaceIP(intf)
 		if err != nil {
-			s.logf("want to boot %s on %s, but couldn't find a unicast source address on that interface: %s", addr, intf.Name, err)
+			s.log("PXE", "Want to boot %s (%s) on %s, but couldn't get a source address: %s", pkt.HardwareAddr, addr, intf.Name, err)
 			continue
 		}
 
 		resp, err := s.offerPXE(pkt, serverIP, fwtype)
 		if err != nil {
-			s.logf("failed to construct PXE response for %s: %s", addr, err)
+			s.log("PXE", "Failed to construct PXE offer for %s (%s): %s", pkt.HardwareAddr, addr, err)
 			continue
 		}
 
 		bs, err := resp.Marshal()
 		if err != nil {
-			s.logf("failed to marshal PXE response for %s: %s", addr, err)
+			s.log("PXE", "Failed to marshal PXE offer for %s (%s): %s", pkt.HardwareAddr, addr, err)
 		}
 
 		if _, err := l.WriteTo(bs, &ipv4.ControlMessage{
 			IfIndex: msg.IfIndex,
 		}, addr); err != nil {
-			s.logf("failed to send PXE response to %s: %s", addr, err)
+			s.log("PXE", "Failed to send PXE response to %s (%s): %s", pkt.HardwareAddr, addr, err)
 		}
 	}
 }
 
 func (s *Server) validatePXE(pkt *dhcp4.Packet) (fwtype Firmware, err error) {
-	if pkt.Type != dhcp4.MsgRequest {
-		return 0, errors.New("not a DHCPREQUEST packet")
-	}
-
-	if pkt.Options[93] == nil {
-		return 0, errors.New("not a PXE boot request (missing option 93)")
-	}
 	fwt, err := pkt.Options.Uint16(93)
 	if err != nil {
 		return 0, fmt.Errorf("malformed DHCP option 93 (required for PXE): %s", err)

pixiecore/tftp.go

@@ -17,6 +17,7 @@ package pixiecore
 import (
 	"bytes"
 	"errors"
+	"fmt"
 	"io"
 	"io/ioutil"
 	"net"
@@ -27,8 +28,9 @@ import (
 
 func (s *Server) serveTFTP(l net.PacketConn) {
 	ts := tftp.Server{
-		Handler: s.handleTFTP,
+		Handler:     s.handleTFTP,
-		InfoLog: func(msg string) { s.logf(msg) },
+		InfoLog:     func(msg string) { s.debug("TFTP", msg) },
+		TransferLog: s.logTFTPTransfer,
 	}
 	err := ts.Serve(l)
 	if err != nil {
@@ -38,7 +40,15 @@ func (s *Server) serveTFTP(l net.PacketConn) {
 		// shutdown and return the error from Serve(). This "log +
 		// randomly stop a piece of pixiecore" is a terrible
 		// kludge.
-		s.logf("TFTP server shut down unexpectedly: %s", err)
+		s.log("TFTP", "Server shut down unexpectedly: %s", err)
+	}
+}
+
+func (s *Server) logTFTPTransfer(clientAddr net.Addr, path string, err error) {
+	if err != nil {
+		s.log("TFTP", "Send of %q to %s failed: %s", path, clientAddr, err)
+	} else {
+		s.log("TFTP", "Sent %q to %s", path, clientAddr)
 	}
 }
 
@@ -50,7 +60,7 @@ func (s *Server) handleTFTP(path string, clientAddr net.Addr) (io.ReadCloser, in
 
 	bs, ok := s.Ipxe[Firmware(i)]
 	if !ok {
-		return nil, 0, errors.New("not found")
+		return nil, 0, fmt.Errorf("unknown firmware type %d", i)
 	}
 
 	return ioutil.NopCloser(bytes.NewBuffer(bs)), int64(len(bs)), nil