start adding go stdlib tracing

cmd/routed/main.go

@@ -9,6 +9,8 @@ import (
 	"net/http"
 	"time"
 
+	_ "git.xeserv.us/xena/route/internal"
+	"git.xeserv.us/xena/route/internal/middleware"
 	"git.xeserv.us/xena/route/internal/routecrypto"
 	"git.xeserv.us/xena/route/internal/server"
 	"github.com/Xe/ln"
@@ -52,7 +54,7 @@ func main() {
 	defer l.Close()
 
 	hs := &http.Server{
-		Handler: s,
+		Handler: middleware.Trace(s),
 		Addr:    scfg.WebAddr,
 	}
 
@@ -61,7 +63,7 @@ func main() {
 
 func setupTLS(s *server.Server, scfg server.Config) {
 	hs := &http.Server{
-		Handler: s,
+		Handler: middleware.Trace(s),
 		Addr:    scfg.SSLAddr,
 		TLSConfig: &tls.Config{
 			GetCertificate: s.GetCertificate,

internal/gops.go

@@ -1,4 +1,4 @@
-package main
+package internal
 
 import (
 	"log"

internal/init.go

@@ -0,0 +1,11 @@
+// Package internal contains autoloading packages and tools.
+package internal
+
+import (
+	"github.com/Xe/ln"
+	"github.com/Xe/ln/ex"
+)
+
+func init() {
+	ln.DefaultLogger.Filters = append(ln.DefaultLogger.Filters, ex.NewGoTraceLogger())
+}

internal/manhole.go

@@ -0,0 +1,27 @@
+package internal
+
+import (
+	"log"
+	"net"
+	"net/http"
+	"net/rpc"
+
+	// Add HTTP pprof routes
+	_ "net/http/pprof"
+
+	// Add tracing routes
+	_ "golang.org/x/net/trace"
+)
+
+func init() {
+	l, err := net.Listen("tcp", "127.0.0.1:0")
+	if err != nil {
+		log.Printf("manhole: cannot bind to 127.0.0.1:0: %v", err)
+		return
+	}
+
+	log.Printf("manhole: Now listening on http://%s", l.Addr())
+
+	rpc.HandleHTTP()
+	go http.Serve(l, nil)
+}

internal/middleware/trace.go

@@ -0,0 +1,41 @@
+package middleware
+
+import (
+	"context"
+	"net/http"
+	"os"
+	"path/filepath"
+	"time"
+
+	"github.com/Xe/ln"
+	"golang.org/x/net/trace"
+)
+
+// Trace adds go stdlib tracing to this http handler.
+func Trace(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		sp := trace.New(filepath.Base(os.Args[0]), "http://"+r.Host+r.RequestURI)
+		defer sp.Finish()
+		ctx, cancel := context.WithTimeout(r.Context(), 30*time.Second)
+		defer cancel()
+
+		ctx = trace.NewContext(ctx, sp)
+		f := ln.F{
+			"method":      r.Method,
+			"path":        r.URL.Path,
+			"remote_addr": r.RemoteAddr,
+			"user_agent":  r.UserAgent(),
+		}
+
+		next.ServeHTTP(w, r.WithContext(ctx))
+
+		ws, ok := w.(interface {
+			Status() int
+		})
+		if ok {
+			f["status"] = ws.Status()
+		}
+
+		ln.Log(ctx, f)
+	})
+}

vendor-log

@@ -325,3 +325,8 @@ b6e1ae21643682ce023deb8d152024597b0e9bb4	golang.org/x/sys/unix
 8443e311d3925f5e20494496790670942ed48504	google.golang.org/grpc/transport
 466e05b2ef3e48ce08a367b6aaac09ee29a124e5	github.com/Xe/ln
 2b3a18b5f0fb6b4f9190549597d3f962c02bc5eb	github.com/pkg/errors
+466e05b2ef3e48ce08a367b6aaac09ee29a124e5	github.com/Xe/ln
+466e05b2ef3e48ce08a367b6aaac09ee29a124e5	github.com/Xe/ln/ex
+2b3a18b5f0fb6b4f9190549597d3f962c02bc5eb	github.com/pkg/errors
+0a9397675ba34b2845f758fe3cd68828369c6517	golang.org/x/net/internal/timeseries
+0a9397675ba34b2845f758fe3cd68828369c6517	golang.org/x/net/trace

vendor/github.com/Xe/ln/ex/doc.go

@@ -0,0 +1,7 @@
+/*
+Package ex is a set of extensions and middleware for ln.
+
+This package will (inevitably) have a lot of third-party dependencies and
+as such might be broken apart into other packages in the future.
+*/
+package ex

vendor/github.com/Xe/ln/ex/gotrace.go

@@ -0,0 +1,68 @@
+package ex
+
+import (
+	"context"
+	"log"
+
+	"github.com/Xe/ln"
+	"golang.org/x/net/trace"
+)
+
+type goEventLogger struct {
+	ev trace.EventLog
+}
+
+// NewGoEventLogger will log ln information to a given trace.EventLog instance.
+func NewGoEventLogger(ev trace.EventLog) ln.Filter {
+	return &goEventLogger{ev: ev}
+}
+
+func (gel *goEventLogger) Apply(ctx context.Context, e ln.Event) bool {
+	data, err := ln.DefaultFormatter.Format(ctx, e)
+	if err != nil {
+		log.Printf("wtf: error in log formatting: %v", err)
+		return false
+	}
+
+	if everr := e.Data["err"]; everr != nil {
+		gel.ev.Errorf("%s", string(data))
+		return true
+	}
+
+	gel.ev.Printf("%s", string(data))
+	return true
+}
+
+func (gel *goEventLogger) Close() { gel.ev.Finish() }
+func (gel *goEventLogger) Run()   {}
+
+type sst string
+
+func (s sst) String() string { return string(s) }
+
+func goTraceLogger(ctx context.Context, e ln.Event) bool {
+	sp, ok := trace.FromContext(ctx)
+	if !ok {
+		return true // no trace in context
+	}
+
+	data, err := ln.DefaultFormatter.Format(ctx, e)
+	if err != nil {
+		log.Printf("wtf: error in log formatting: %v", err)
+		return false
+	}
+
+	if everr := e.Data["err"]; everr != nil {
+		sp.SetError()
+	}
+
+	sp.LazyLog(sst(string(data)), false)
+
+	return true
+}
+
+// NewGoTraceLogger will log ln information to a golang.org/x/net/trace.Trace
+// if it is present in the context of ln calls.
+func NewGoTraceLogger() ln.Filter {
+	return ln.FilterFunc(goTraceLogger)
+}

vendor/github.com/Xe/ln/ex/http.go

@@ -0,0 +1,36 @@
+package ex
+
+import (
+	"net"
+	"net/http"
+	"time"
+
+	"github.com/Xe/ln"
+)
+
+func HTTPLog(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		host, _, _ := net.SplitHostPort(r.RemoteAddr)
+		f := ln.F{
+			"remote_ip":       host,
+			"x_forwarded_for": r.Header.Get("X-Forwarded-For"),
+			"path":            r.URL.Path,
+		}
+		ctx := ln.WithF(r.Context(), f)
+		st := time.Now()
+
+		next.ServeHTTP(w, r.WithContext(ctx))
+
+		af := time.Now()
+		f["request_duration"] = af.Sub(st)
+
+		ws, ok := w.(interface {
+			Status() int
+		})
+		if ok {
+			f["status"] = ws.Status()
+		}
+
+		ln.Log(r.Context(), f)
+	})
+}

vendor/github.com/Xe/ln/ex/l2met.go

@@ -0,0 +1,25 @@
+package ex
+
+import (
+	"time"
+
+	"github.com/Xe/ln"
+)
+
+// This file deals with formatting of [l2met] style metrics.
+// [l2met]: https://r.32k.io/l2met-introduction
+
+// Counter formats a value as a metrics counter.
+func Counter(name string, value int) ln.Fer {
+	return ln.F{"count#" + name: value}
+}
+
+// Gauge formats a value as a metrics gauge.
+func Gauge(name string, value int) ln.Fer {
+	return ln.F{"gauge#" + name: value}
+}
+
+// Measure formats a value as a metrics measure.
+func Measure(name string, ts time.Time) ln.Fer {
+	return ln.F{"measure#" + name: time.Since(ts)}
+}