From 4aa8885728215efc4aec2deefc9fdeb3a4a9a9e8 Mon Sep 17 00:00:00 2001 From: David Anderson Date: Mon, 15 Aug 2016 21:33:57 -0700 Subject: [PATCH] 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 | 3 +- pixiecore/cli/bootcmd.go | 3 +- pixiecore/cli/v1compat.go | 6 ++-- pixiecore/dhcp.go | 35 +++++++++++++------- pixiecore/http.go | 69 +++++++++++++++++++++++++++++---------- pixiecore/http_test.go | 11 +++++-- pixiecore/logging.go | 23 ++++++++----- pixiecore/pixiecore.go | 36 ++++++++------------ pixiecore/pxe.go | 28 +++++++--------- pixiecore/tftp.go | 18 +++++++--- 10 files changed, 146 insertions(+), 86 deletions(-) diff --git a/pixiecore/cli/apicmd.go b/pixiecore/cli/apicmd.go index eb3a8ce..fb1780f 100644 --- a/pixiecore/cli/apicmd.go +++ b/pixiecore/cli/apicmd.go @@ -48,7 +48,8 @@ the Pixiecore boot API. The specification can be found at .`, s := &pixiecore.Server{ Booter: booter, Ipxe: Ipxe, - Log: func(msg string) { fmt.Println(msg) }, + Log: logStdout, + Debug: debugLog, } fmt.Println(s.Serve()) }} diff --git a/pixiecore/cli/bootcmd.go b/pixiecore/cli/bootcmd.go index cab562b..0463045 100644 --- a/pixiecore/cli/bootcmd.go +++ b/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()) }, diff --git a/pixiecore/cli/v1compat.go b/pixiecore/cli/v1compat.go index ec039a1..55b41e6 100644 --- a/pixiecore/cli/v1compat.go +++ b/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, diff --git a/pixiecore/dhcp.go b/pixiecore/dhcp.go index 4e7eef8..9886b30 100644 --- a/pixiecore/dhcp.go +++ b/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") } diff --git a/pixiecore/http.go b/pixiecore/http.go index 3884f77..798b2da 100644 --- a/pixiecore/http.go +++ b/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{}) { - s.logHTTP(r, format, args...) - http.Error(w, fmt.Sprintf(format, args...), status) +func (s *Server) serveHTTP(l net.Listener) { + httpMux := http.NewServeMux() + 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() - mac, err := net.ParseMAC(args.Get("mac")) - if err != nil { - s.httpError(w, r, http.StatusBadRequest, "invalid MAC address %q: %s\n", args.Get("mac"), err) + macStr := r.URL.Query().Get("mac") + if macStr == "" { + s.debug("HTTP", "Bad request %q from %s, missing MAC address", r.URL, r.RemoteAddr) + 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.logHTTP(r, "error getting bootspec for %#v: %s", mach, err) + s.log("HTTP", "Couldn't get a bootspec for %s (query %q from %s): %s", mac, r.URL, r.RemoteAddr, 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) - http.Error(w, "couldn't get a bootspec", http.StatusInternalServerError) + 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 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) { diff --git a/pixiecore/http_test.go b/pixiecore/http_test.go index 45d5855..e5e94d9 100644 --- a/pixiecore/http_test.go +++ b/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) diff --git a/pixiecore/logging.go b/pixiecore/logging.go index 18f3709..f6ac580 100644 --- a/pixiecore/logging.go +++ b/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 -// that caused the statement to be logged. -func (s *Server) logHTTP(r *http.Request, format string, args ...interface{}) { - if s.Log != nil { - pfx := fmt.Sprintf("HTTP request for %s from %s: ", r.URL, r.RemoteAddr) - s.logf(pfx+format, args...) +func (s *Server) debug(subsystem, format string, args ...interface{}) { + if s.Debug == nil { + return } + 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))) } diff --git a/pixiecore/pixiecore.go b/pixiecore/pixiecore.go index 9ce1b5f..263e2b9 100644 --- a/pixiecore/pixiecore.go +++ b/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. - // - // TODO: until Trace is better defined and plumbed through, we use - // Log extensively, which may make it too noisy for normal - // use. Need to decide what, if anything, we should do about that. - Log func(msg string) + Log func(subsystem, msg string) + // Debug receives extensive logging on Pixiecore's internals. Very + // useful for debugging, but very verbose. + Debug func(subsystem, 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) - http.HandleFunc("/_/file", s.handleFile) - http.ListenAndServe(fmt.Sprintf("%s:%d", s.Address, s.HTTPPort), nil) - - return nil + go s.serveHTTP(http) + select {} } diff --git a/pixiecore/pxe.go b/pixiecore/pxe.go index 05aa80d..1767c02 100644 --- a/pixiecore/pxe.go +++ b/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) diff --git a/pixiecore/tftp.go b/pixiecore/tftp.go index 06270f0..3490beb 100644 --- a/pixiecore/tftp.go +++ b/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, - InfoLog: func(msg string) { s.logf(msg) }, + Handler: s.handleTFTP, + 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