Merge pull request #11 from jacobweinstock/otel

Add open telemetry to the HTTP service:

example/main.go

@@ -15,7 +15,13 @@ import (
 )
 
 func main() {
-	ctx, done := signal.NotifyContext(context.Background(), os.Interrupt, syscall.SIGHUP, syscall.SIGTERM)
+	ctx := context.Background()
+	/*
+		ctx, otelShutdown := otelinit.InitOpenTelemetry(ctx, "ipxe")
+		defer otelShutdown(ctx)
+	*/
+
+	ctx, done := signal.NotifyContext(ctx, os.Interrupt, syscall.SIGHUP, syscall.SIGTERM)
 	defer done()
 	logger := stdr.New(log.New(os.Stdout, "", log.Lshortfile))
 

ihttp/ihttp.go

@@ -1,17 +1,22 @@
-// Package http implements an HTTP server for iPXE binaries.
+// Package ihttp implements an HTTP server for iPXE binaries.
 package ihttp
 
 import (
 	"context"
+	"fmt"
 	"net"
 	"net/http"
 	"path"
 	"path/filepath"
+	"regexp"
 	"strings"
-	"unicode/utf8"
 
 	"github.com/go-logr/logr"
 	"github.com/tinkerbell/ipxedust/binary"
+	"go.opentelemetry.io/otel"
+	"go.opentelemetry.io/otel/attribute"
+	"go.opentelemetry.io/otel/codes"
+	"go.opentelemetry.io/otel/trace"
 	"inet.af/netaddr"
 )
 
@@ -44,11 +49,6 @@ func Serve(_ context.Context, conn net.Listener, h *http.Server) error {
 	return h.Serve(conn)
 }
 
-func trimFirstRune(s string) string {
-	_, i := utf8.DecodeRuneInString(s)
-	return s[i:]
-}
-
 // Handle handles responses to HTTP requests.
 func (s Handler) Handle(w http.ResponseWriter, req *http.Request) {
 	s.Log.V(1).Info("handling request", "method", req.Method, "path", req.URL.Path)
@@ -57,28 +57,85 @@ func (s Handler) Handle(w http.ResponseWriter, req *http.Request) {
 		return
 	}
 	host, port, _ := net.SplitHostPort(req.RemoteAddr)
-	s.Log = s.Log.WithValues("host", host, "port", port)
-	m := path.Dir(req.URL.Path)
-	if strings.HasPrefix(m, "/") {
-		m = trimFirstRune(path.Dir(req.URL.Path))
+	log := s.Log.WithValues("host", host, "port", port)
+	// If a mac address is provided (/0a:00:27:00:00:02/snp.efi), parse and log it.
+	// Mac address is optional.
+	optionalMac, _ := net.ParseMAC(strings.TrimPrefix(path.Dir(req.URL.Path), "/"))
+	log = log.WithValues("macFromURI", optionalMac.String())
+	filename := filepath.Base(req.URL.Path)
+	log = log.WithValues("filename", filename)
+
+	// clients can send traceparent over HTTP by appending the traceparent string
+	// to the end of the filename they really want
+	longfile := filename // hang onto this to report in traces
+	ctx, shortfile, err := extractTraceparentFromFilename(context.Background(), filename)
+	if err != nil {
+		log.Error(err, "failed to extract traceparent from filename")
 	}
-	// If a mac address is provided, log it. Mac address is optional.
-	// Mac address would be useful for logging and tracing.
-	mac, _ := net.ParseMAC(m)
-	s.Log = s.Log.WithValues("mac", mac)
+	if shortfile != filename {
+		log = log.WithValues("shortfile", shortfile)
+		log.Info("traceparent found in filename", "filenameWithTraceparent", longfile)
+		filename = shortfile
+	}
+
+	tracer := otel.Tracer("HTTP")
+	_, span := tracer.Start(ctx, "HTTP get",
+		trace.WithSpanKind(trace.SpanKindServer),
+		trace.WithAttributes(attribute.String("filename", filename)),
+		trace.WithAttributes(attribute.String("requested-filename", longfile)),
+		trace.WithAttributes(attribute.String("ip", host)),
+		trace.WithAttributes(attribute.String("mac", optionalMac.String())),
+	)
+
+	span.SetStatus(codes.Ok, filename)
+	span.End()
 
-	got := filepath.Base(req.URL.Path)
-	file, found := binary.Files[got]
+	file, found := binary.Files[filename]
 	if !found {
-		s.Log.Info("requested file not found", "file", got)
+		log.Info("requested file not found")
 		http.NotFound(w, req)
 		return
 	}
 	b, err := w.Write(file)
 	if err != nil {
-		s.Log.Error(err, "error serving file")
+		log.Error(err, "error serving file")
 		w.WriteHeader(http.StatusInternalServerError)
 		return
 	}
-	s.Log.Info("file served", "bytes sent", b, "file size", len(file), "file", got)
+	log.Info("file served", "bytesSent", b, "fileSize", len(file))
+}
+
+// extractTraceparentFromFilename takes a context and filename and checks the filename for
+// a traceparent tacked onto the end of it. If there is a match, the traceparent is extracted
+// and a new SpanContext is constructed and added to the context.Context that is returned.
+// The filename is shortened to just the original filename so the rest of boots HTTP can
+// carry on as usual.
+func extractTraceparentFromFilename(ctx context.Context, filename string) (context.Context, string, error) {
+	// traceparentRe captures 4 items, the original filename, the trace id, span id, and trace flags
+	traceparentRe := regexp.MustCompile("^(.*)-[[:xdigit:]]{2}-([[:xdigit:]]{32})-([[:xdigit:]]{16})-([[:xdigit:]]{2})")
+	parts := traceparentRe.FindStringSubmatch(filename)
+	if len(parts) == 5 {
+		traceID, err := trace.TraceIDFromHex(parts[2])
+		if err != nil {
+			return ctx, filename, fmt.Errorf("parsing OpenTelemetry trace id %q failed: %w", parts[2], err)
+		}
+
+		spanID, err := trace.SpanIDFromHex(parts[3])
+		if err != nil {
+			return ctx, filename, fmt.Errorf("parsing OpenTelemetry span id %q failed: %w", parts[3], err)
+		}
+
+		// create a span context with the parent trace id & span id
+		spanCtx := trace.NewSpanContext(trace.SpanContextConfig{
+			TraceID:    traceID,
+			SpanID:     spanID,
+			Remote:     true,
+			TraceFlags: trace.FlagsSampled, // TODO: use the parts[4] value instead
+		})
+
+		// inject it into the context.Context and return it along with the original filename
+		return trace.ContextWithSpanContext(ctx, spanCtx), parts[1], nil
+	}
+	// no traceparent found, return everything as it was
+	return ctx, filename, nil
 }

ihttp/ihttp_test.go

@@ -3,16 +3,21 @@ package ihttp
 import (
 	"bytes"
 	"context"
+	"errors"
 	"fmt"
 	"io"
 	"io/ioutil"
+	"log"
 	"net/http"
 	"net/http/httptest"
+	"os"
 	"testing"
 
 	"github.com/go-logr/logr"
+	"github.com/go-logr/stdr"
 	"github.com/google/go-cmp/cmp"
 	"github.com/tinkerbell/ipxedust/binary"
+	"go.opentelemetry.io/otel/trace"
 	"inet.af/netaddr"
 )
 
@@ -94,7 +99,7 @@ func TestListenAndServeHTTP(t *testing.T) {
 	}
 }
 
-func TestHandleHTTP_Handler(t *testing.T) {
+func TestHandle(t *testing.T) {
 	type req struct {
 		method string
 		url    string
@@ -115,12 +120,20 @@ func TestHandleHTTP_Handler(t *testing.T) {
 		},
 		{
 			name: "success",
-			req:  req{method: "GET", url: "/snp.efi"},
+			req:  req{method: "GET", url: "/30:23:03:73:a5:a7/snp.efi-00-23b1e307bb35484f535a1f772c06910e-d887dc3912240434-01"},
 			want: &http.Response{
 				StatusCode: http.StatusOK,
 				Body:       ioutil.NopCloser(bytes.NewBuffer(binary.Files["snp.efi"])),
 			},
 		},
+		{
+			name: "fail with bad traceparent",
+			req:  req{method: "GET", url: "/30:23:03:73:a5:a7/snp.efi-00-00000000000000000000000000000000-d887dc3912240434-01"},
+			want: &http.Response{
+				StatusCode: http.StatusNotFound,
+				Body:       nil,
+			},
+		},
 		{
 			name: "file not found",
 			req:  req{method: "GET", url: "/none.efi"},
@@ -140,16 +153,17 @@ func TestHandleHTTP_Handler(t *testing.T) {
 
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {
+			logger := stdr.New(log.New(os.Stdout, "", log.Lshortfile))
 			req := httptest.NewRequest(tt.req.method, tt.req.url, tt.req.body)
 			var resp *http.Response
 			if tt.failWrite {
 				w := newFakeResponse()
-				h := Handler{Log: logr.Discard()}
+				h := Handler{Log: logger}
 				h.Handle(w, req)
 				resp = w.Result()
 			} else {
 				w := httptest.NewRecorder()
-				h := Handler{Log: logr.Discard()}
+				h := Handler{Log: logger}
 				h.Handle(w, req)
 				resp = w.Result()
 			}
@@ -175,3 +189,74 @@ func TestHandleHTTP_Handler(t *testing.T) {
 		})
 	}
 }
+
+func TestExtractTraceparentFromFilename(t *testing.T) {
+	tests := map[string]struct {
+		fileIn  string
+		fileOut string
+		err     error
+		spanID  string
+		traceID string
+	}{
+		"do nothing when no tp": {fileIn: "undionly.ipxe", fileOut: "undionly.ipxe", err: nil},
+		"ignore bad filename": {
+			fileIn:  "undionly.ipxe-00-0000-0000-00",
+			fileOut: "undionly.ipxe-00-0000-0000-00",
+			err:     nil,
+		},
+		"ignore corrupt tp": {
+			fileIn:  "undionly.ipxe-00-xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx-abcdefghijklmnop-01",
+			fileOut: "undionly.ipxe-00-xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx-abcdefghijklmnop-01",
+			err:     nil,
+		},
+		"ignore corrupt TraceID": {
+			fileIn:  "undionly.ipxe-00-00000000000000000000000000000000-0000000000000000-01",
+			fileOut: "undionly.ipxe-00-00000000000000000000000000000000-0000000000000000-01",
+			err:     fmt.Errorf("parsing OpenTelemetry trace id %q failed: %w", "00000000000000000000000000000000", fmt.Errorf("trace-id can't be all zero")),
+		},
+		"ignore corrupt SpanID": {
+			fileIn:  "undionly.ipxe-00-11111111111111111111111111111111-0000000000000000-01",
+			fileOut: "undionly.ipxe-00-11111111111111111111111111111111-0000000000000000-01",
+			err:     fmt.Errorf("parsing OpenTelemetry span id %q failed: %w", "0000000000000000", fmt.Errorf("span-id can't be all zero")),
+		},
+		"extract tp": {
+			fileIn:  "undionly.ipxe-00-23b1e307bb35484f535a1f772c06910e-d887dc3912240434-01",
+			fileOut: "undionly.ipxe",
+			err:     nil,
+			spanID:  "d887dc3912240434",
+			traceID: "23b1e307bb35484f535a1f772c06910e",
+		},
+	}
+
+	for name, tc := range tests {
+		t.Run(name, func(t *testing.T) {
+			ctx := context.Background()
+			ctx, outfile, err := extractTraceparentFromFilename(ctx, tc.fileIn)
+			if !errors.Is(err, tc.err) {
+				if diff := cmp.Diff(fmt.Sprint(err), fmt.Sprint(tc.err)); diff != "" {
+					t.Errorf(diff)
+					t.Errorf("filename %q should have resulted in error %q but got %q", tc.fileIn, tc.err, err)
+				}
+			}
+			if outfile != tc.fileOut {
+				t.Errorf("filename %q should have resulted in %q but got %q", tc.fileIn, tc.fileOut, outfile)
+			}
+
+			if tc.spanID != "" {
+				sc := trace.SpanContextFromContext(ctx)
+				got := sc.SpanID().String()
+				if tc.spanID != got {
+					t.Errorf("got incorrect span id from context, expected %q but got %q", tc.spanID, got)
+				}
+			}
+
+			if tc.traceID != "" {
+				sc := trace.SpanContextFromContext(ctx)
+				got := sc.TraceID().String()
+				if tc.traceID != got {
+					t.Errorf("got incorrect trace id from context, expected %q but got %q", tc.traceID, got)
+				}
+			}
+		})
+	}
+}

ipxedust.go

@@ -1,4 +1,4 @@
-// Package ipxe implements the iPXE tftp and http serving.
+// Package ipxedust implements the iPXE tftp and http serving.
 package ipxedust
 
 import (

itftp/itftp.go

@@ -1,4 +1,4 @@
-// Package tftp implements a TFTP server for iPXE binaries.
+// Package itftp implements a TFTP server for iPXE binaries.
 package itftp
 
 import (
@@ -54,50 +54,51 @@ func (t Handler) HandleRead(filename string, rf io.ReaderFrom) error {
 
 	full := filename
 	filename = path.Base(filename)
-	l := t.Log.WithValues("event", "get", "filename", filename, "uri", full, "client", client)
+	log := t.Log.WithValues("event", "get", "filename", filename, "uri", full, "client", client)
 
 	// clients can send traceparent over TFTP by appending the traceparent string
 	// to the end of the filename they really want
 	longfile := filename // hang onto this to report in traces
 	ctx, shortfile, err := extractTraceparentFromFilename(context.Background(), filename)
 	if err != nil {
-		l.Error(err, "")
+		log.Error(err, "failed to extract traceparent from filename")
 	}
 	if shortfile != filename {
-		l = l.WithValues("filename", shortfile) // flip to the short filename in logs
-		l.Info("client requested filename '", filename, "' with a traceparent attached and has been shortened to '", shortfile, "'")
+		log = log.WithValues("shortfile", shortfile)
+		log.Info("traceparent found in filename", "filenameWithTraceparent", longfile)
 		filename = shortfile
 	}
-	// If a mac address is provided, log it. Mac address is optional.
-	mac, _ := net.ParseMAC(path.Dir(full))
-	l = l.WithValues("mac", mac.String())
+	// If a mac address is provided (0a:00:27:00:00:02/snp.efi), parse and log it.
+	// Mac address is optional.
+	optionalMac, _ := net.ParseMAC(path.Dir(full))
+	log = log.WithValues("macFromURI", optionalMac.String())
 
 	tracer := otel.Tracer("TFTP")
 	_, span := tracer.Start(ctx, "TFTP get",
 		trace.WithSpanKind(trace.SpanKindServer),
 		trace.WithAttributes(attribute.String("filename", filename)),
 		trace.WithAttributes(attribute.String("requested-filename", longfile)),
 		trace.WithAttributes(attribute.String("ip", client.IP.String())),
-		trace.WithAttributes(attribute.String("mac", mac.String())),
+		trace.WithAttributes(attribute.String("mac", optionalMac.String())),
 	)
 
 	span.SetStatus(codes.Ok, filename)
 	span.End()
 
 	content, ok := binary.Files[filepath.Base(shortfile)]
 	if !ok {
-		err := fmt.Errorf("file unknown: %w", os.ErrNotExist)
-		l.Error(err, "file unknown")
+		err := fmt.Errorf("file [%v] unknown: %w", filepath.Base(shortfile), os.ErrNotExist)
+		log.Error(err, "file unknown")
 		return err
 	}
 	ct := bytes.NewReader(content)
 
 	b, err := rf.ReadFrom(ct)
 	if err != nil {
-		l.Error(err, "file serve failed", "b", b, "content size", len(content))
+		log.Error(err, "file serve failed", "b", b, "contentSize", len(content))
 		return err
 	}
-	l.Info("file served", "bytes sent", b, "content size", len(content))
+	log.Info("file served", "bytesSent", b, "contentSize", len(content))
 	return nil
 }