From 4d05d9b7cdccbc93ad713f91562b285d5b0cff9e Mon Sep 17 00:00:00 2001
From: Christine Dodrill <me@christine.website>
Date: Sun, 1 Oct 2017 05:50:05 -0700
Subject: [PATCH 1/5] update ln

---
 vendor-log                           |  2 ++
 vendor/github.com/Xe/ln/action.go    | 11 ++++++++
 vendor/github.com/Xe/ln/context.go   | 38 +++++++++++++++++++++++++
 vendor/github.com/Xe/ln/filter.go    | 15 +++++-----
 vendor/github.com/Xe/ln/formatter.go |  5 ++--
 vendor/github.com/Xe/ln/logger.go    | 42 ++++++++++++++++------------
 6 files changed, 86 insertions(+), 27 deletions(-)
 create mode 100644 vendor/github.com/Xe/ln/action.go
 create mode 100644 vendor/github.com/Xe/ln/context.go

diff --git a/vendor-log b/vendor-log
index a1b7eed..6495569 100644
--- a/vendor-log
+++ b/vendor-log
@@ -323,3 +323,5 @@ b6e1ae21643682ce023deb8d152024597b0e9bb4	golang.org/x/sys/unix
 8443e311d3925f5e20494496790670942ed48504	google.golang.org/grpc/status
 8443e311d3925f5e20494496790670942ed48504	google.golang.org/grpc/tap
 8443e311d3925f5e20494496790670942ed48504	google.golang.org/grpc/transport
+466e05b2ef3e48ce08a367b6aaac09ee29a124e5	github.com/Xe/ln
+2b3a18b5f0fb6b4f9190549597d3f962c02bc5eb	github.com/pkg/errors
diff --git a/vendor/github.com/Xe/ln/action.go b/vendor/github.com/Xe/ln/action.go
new file mode 100644
index 0000000..54f8954
--- /dev/null
+++ b/vendor/github.com/Xe/ln/action.go
@@ -0,0 +1,11 @@
+package ln
+
+// Action is a convenience helper for logging the "action" being performed as
+// part of a log line.
+//
+// It is a convenience wrapper for the following:
+//
+//     ln.Log(ctx, fer, f, ln.Action("writing frozberry sales reports to database"))
+func Action(act string) Fer {
+	return F{"action": act}
+}
diff --git a/vendor/github.com/Xe/ln/context.go b/vendor/github.com/Xe/ln/context.go
new file mode 100644
index 0000000..0ea3229
--- /dev/null
+++ b/vendor/github.com/Xe/ln/context.go
@@ -0,0 +1,38 @@
+package ln
+
+import (
+	"context"
+)
+
+type ctxKey int
+
+const (
+	fKey = iota
+)
+
+// WithF stores or appends a given F instance into a context.
+func WithF(ctx context.Context, f F) context.Context {
+	pf, ok := FFromContext(ctx)
+	if !ok {
+		return context.WithValue(ctx, fKey, f)
+	}
+
+	pf.Extend(f)
+
+	return context.WithValue(ctx, fKey, pf)
+}
+
+// FFromContext fetches the `F` out of the context if it exists.
+func FFromContext(ctx context.Context) (F, bool) {
+	fvp := ctx.Value(fKey)
+	if fvp == nil {
+		return nil, false
+	}
+
+	f, ok := fvp.(F)
+	if !ok {
+		return nil, false
+	}
+
+	return f, true
+}
diff --git a/vendor/github.com/Xe/ln/filter.go b/vendor/github.com/Xe/ln/filter.go
index 586efef..4f2d006 100644
--- a/vendor/github.com/Xe/ln/filter.go
+++ b/vendor/github.com/Xe/ln/filter.go
@@ -1,23 +1,24 @@
 package ln
 
 import (
+	"context"
 	"io"
 	"sync"
 )
 
 // Filter interface for defining chain filters
 type Filter interface {
-	Apply(Event) bool
+	Apply(ctx context.Context, e Event) bool
 	Run()
 	Close()
 }
 
 // FilterFunc allows simple functions to implement the Filter interface
-type FilterFunc func(e Event) bool
+type FilterFunc func(ctx context.Context, e Event) bool
 
 // Apply implements the Filter interface
-func (ff FilterFunc) Apply(e Event) bool {
-	return ff(e)
+func (ff FilterFunc) Apply(ctx context.Context, e Event) bool {
+	return ff(ctx, e)
 }
 
 // Run implements the Filter interface
@@ -45,8 +46,8 @@ func NewWriterFilter(out io.Writer, format Formatter) *WriterFilter {
 }
 
 // Apply implements the Filter interface
-func (w *WriterFilter) Apply(e Event) bool {
-	output, err := w.Formatter.Format(e)
+func (w *WriterFilter) Apply(ctx context.Context, e Event) bool {
+	output, err := w.Formatter.Format(ctx, e)
 	if err == nil {
 		w.Lock()
 		w.Out.Write(output)
@@ -63,4 +64,4 @@ func (w *WriterFilter) Run() {}
 func (w *WriterFilter) Close() {}
 
 // NilFilter is safe to return as a Filter, but does nothing
-var NilFilter = FilterFunc(func(e Event) bool { return true })
+var NilFilter = FilterFunc(func(_ context.Context, e Event) bool { return true })
diff --git a/vendor/github.com/Xe/ln/formatter.go b/vendor/github.com/Xe/ln/formatter.go
index ecd4743..70313fc 100644
--- a/vendor/github.com/Xe/ln/formatter.go
+++ b/vendor/github.com/Xe/ln/formatter.go
@@ -2,6 +2,7 @@ package ln
 
 import (
 	"bytes"
+	"context"
 	"fmt"
 	"time"
 )
@@ -13,7 +14,7 @@ var (
 
 // Formatter defines the formatting of events
 type Formatter interface {
-	Format(Event) ([]byte, error)
+	Format(ctx context.Context, e Event) ([]byte, error)
 }
 
 // DefaultFormatter is the default way in which to format events
@@ -36,7 +37,7 @@ func NewTextFormatter() Formatter {
 }
 
 // Format implements the Formatter interface
-func (t *TextFormatter) Format(e Event) ([]byte, error) {
+func (t *TextFormatter) Format(_ context.Context, e Event) ([]byte, error) {
 	var writer bytes.Buffer
 
 	writer.WriteString("time=\"")
diff --git a/vendor/github.com/Xe/ln/logger.go b/vendor/github.com/Xe/ln/logger.go
index 47d8b5d..79a9a63 100644
--- a/vendor/github.com/Xe/ln/logger.go
+++ b/vendor/github.com/Xe/ln/logger.go
@@ -1,6 +1,7 @@
 package ln
 
 import (
+	"context"
 	"os"
 	"time"
 
@@ -61,7 +62,7 @@ type Event struct {
 }
 
 // Log is the generic logging method.
-func (l *Logger) Log(xs ...Fer) {
+func (l *Logger) Log(ctx context.Context, xs ...Fer) {
 	event := Event{Time: time.Now()}
 
 	addF := func(bf F) {
@@ -78,6 +79,11 @@ func (l *Logger) Log(xs ...Fer) {
 		addF(f.F())
 	}
 
+	ctxf, ok := FFromContext(ctx)
+	if ok {
+		addF(ctxf)
+	}
+
 	if os.Getenv("LN_DEBUG_ALL_EVENTS") == "1" {
 		frame := callersFrame()
 		if event.Data == nil {
@@ -88,19 +94,19 @@ func (l *Logger) Log(xs ...Fer) {
 		event.Data["_filename"] = frame.filename
 	}
 
-	l.filter(event)
+	l.filter(ctx, event)
 }
 
-func (l *Logger) filter(e Event) {
+func (l *Logger) filter(ctx context.Context, e Event) {
 	for _, f := range l.Filters {
-		if !f.Apply(e) {
+		if !f.Apply(ctx, e) {
 			return
 		}
 	}
 }
 
 // Error logs an error and information about the context of said error.
-func (l *Logger) Error(err error, xs ...Fer) {
+func (l *Logger) Error(ctx context.Context, err error, xs ...Fer) {
 	data := F{}
 	frame := callersFrame()
 
@@ -116,20 +122,20 @@ func (l *Logger) Error(err error, xs ...Fer) {
 
 	xs = append(xs, data)
 
-	l.Log(xs...)
+	l.Log(ctx, xs...)
 }
 
 // Fatal logs this set of values, then exits with status code 1.
-func (l *Logger) Fatal(xs ...Fer) {
+func (l *Logger) Fatal(ctx context.Context, xs ...Fer) {
 	xs = append(xs, F{"fatal": true})
 
-	l.Log(xs...)
+	l.Log(ctx, xs...)
 
 	os.Exit(1)
 }
 
 // FatalErr combines Fatal and Error.
-func (l *Logger) FatalErr(err error, xs ...Fer) {
+func (l *Logger) FatalErr(ctx context.Context, err error, xs ...Fer) {
 	xs = append(xs, F{"fatal": true})
 
 	data := F{}
@@ -146,7 +152,7 @@ func (l *Logger) FatalErr(err error, xs ...Fer) {
 	}
 
 	xs = append(xs, data)
-	l.Log(xs...)
+	l.Log(ctx, xs...)
 
 	os.Exit(1)
 }
@@ -154,21 +160,21 @@ func (l *Logger) FatalErr(err error, xs ...Fer) {
 // Default Implementation
 
 // Log is the generic logging method.
-func Log(xs ...Fer) {
-	DefaultLogger.Log(xs...)
+func Log(ctx context.Context, xs ...Fer) {
+	DefaultLogger.Log(ctx, xs...)
 }
 
 // Error logs an error and information about the context of said error.
-func Error(err error, xs ...Fer) {
-	DefaultLogger.Error(err, xs...)
+func Error(ctx context.Context, err error, xs ...Fer) {
+	DefaultLogger.Error(ctx, err, xs...)
 }
 
 // Fatal logs this set of values, then exits with status code 1.
-func Fatal(xs ...Fer) {
-	DefaultLogger.Fatal(xs...)
+func Fatal(ctx context.Context, xs ...Fer) {
+	DefaultLogger.Fatal(ctx, xs...)
 }
 
 // FatalErr combines Fatal and Error.
-func FatalErr(err error, xs ...Fer) {
-	DefaultLogger.FatalErr(err, xs...)
+func FatalErr(ctx context.Context, err error, xs ...Fer) {
+	DefaultLogger.FatalErr(ctx, err, xs...)
 }

From f69257f5f8a5e01b7fa0d9746b9a948288700848 Mon Sep 17 00:00:00 2001
From: Christine Dodrill <me@christine.website>
Date: Sun, 1 Oct 2017 06:28:13 -0700
Subject: [PATCH 2/5] all: update use of ln

---
 cmd/route-cli/main.go       | 46 ++++++++++++++++++++-----------
 cmd/route-httpagent/main.go |  7 ++---
 cmd/routed/main.go          | 15 +++++++----
 internal/database/boltdb.go |  2 +-
 internal/server/common.go   |  2 +-
 internal/server/route.go    | 12 ++++-----
 lib/tun2/connection.go      | 14 ++++++----
 lib/tun2/server.go          | 54 ++++++++++++++++++++-----------------
 8 files changed, 88 insertions(+), 64 deletions(-)

diff --git a/cmd/route-cli/main.go b/cmd/route-cli/main.go
index a069f5f..9d1b87f 100644
--- a/cmd/route-cli/main.go
+++ b/cmd/route-cli/main.go
@@ -31,6 +31,7 @@ var allScopes = []string{
 	"token:get", "token:getall", "token:put", "token:delete", "token:deactivate",
 	"route:get", "route:getall", "route:put", "route:delete",
 	"connect",
+	"admin",
 }
 
 var whoami string
@@ -123,10 +124,21 @@ func handle(w http.ResponseWriter, r *http.Request) {
 
 func main() {
 	cmdline := kingpin.MustParse(app.Parse(os.Args[1:]))
+	ctx, cancel := context.WithCancel(context.Background())
+	defer cancel()
 
+retry_netrc:
 	n, err := netrc.Parse(*netrcPath)
 	if err != nil {
-		ln.Fatal(ln.F{"err": err, "action": "netrc.Parse"})
+		_, err := os.Stat(*netrcPath)
+		if err == os.ErrNotExist {
+			fout, err := os.Create(*netrcPath)
+			if err != nil {
+				ln.FatalErr(ctx, err, ln.Action("creating netrc"), ln.F{"path": *netrcPath})
+			}
+			fout.Close()
+			goto retry_netrc
+		}
 	}
 	_ = n
 
@@ -134,30 +146,30 @@ func main() {
 	case "test-server":
 		http.HandleFunc("/", handle)
 
-		ln.Fatal(ln.F{"err": http.ListenAndServe(*testServerAddr, nil), "action": "test_server"})
+		ln.FatalErr(ctx, http.ListenAndServe(*testServerAddr, nil), ln.Action("test server listenAndServe"))
 
 	case "generate-key":
 		key, err := routecrypto.GenerateKey()
 		if err != nil {
-			ln.Fatal(ln.F{"err": err, "action": "routecrypto.GenerateKey"})
+			ln.FatalErr(ctx, err, ln.Action("generating encryption key"))
 		}
 
 		fmt.Println("Your key is:", routecrypto.ShowKey(key))
 	case "token generate-root":
 		key, err := routecrypto.ParseKey(*tokenGenerateKey)
 		if err != nil {
-			ln.Fatal(ln.F{"err": err, "action": "routecrypto.ParseKey"})
+			ln.FatalErr(ctx, err, ln.Action("parsing encryption key"))
 		}
 		db, err := database.NewBoltStorage(*tokenGenerateDatabasePath, key)
 		if err != nil {
-			ln.Fatal(ln.F{"err": err, "action": "database.NewBoltStorage"})
+			ln.FatalErr(ctx, err, ln.Action("opening routed database"))
 		}
 
 		tBody := uuid.New()
 
 		_, err = db.PutToken(context.Background(), tBody, *tokenGenerateUsername, *tokenGenerateScopes)
 		if err != nil {
-			ln.Fatal(ln.F{"err": err, "action": "db.PutToken"})
+			ln.FatalErr(ctx, err, ln.Action("add newly created token to database"))
 		}
 		defer db.Close()
 
@@ -166,7 +178,7 @@ func main() {
 		n.AddMachine(*grpcServer, *tokenGenerateUsername, tBody)
 		err = n.Save()
 		if err != nil {
-			ln.Fatal(ln.F{"err": err, "action": "n.Save"})
+			ln.FatalErr(ctx, err, ln.Action("add machine to netrc"))
 		}
 
 		return
@@ -182,7 +194,7 @@ func main() {
 		grpc.WithTransportCredentials(connCreds),
 		grpc.WithPerRPCCredentials(creds))
 	if err != nil {
-		ln.Fatal(ln.F{"err": err, "action": "grpc.Dial"})
+		ln.FatalErr(ctx, err, ln.Action("dialing grpc server"), ln.F{"hostname": *grpcServer})
 	}
 
 	rc := proto.NewRoutesClient(conn)
@@ -195,19 +207,21 @@ func main() {
 
 	switch cmdline {
 	case "route create":
-		idr, err := rc.Put(context.Background(), &proto.Route{Host: *routesCreateDomain})
+		idr, err := rc.Put(ctx, &proto.Route{Host: *routesCreateDomain})
 		if err != nil {
-			ln.Fatal(ln.F{"err": err, "action": "rc.Put"})
+			ln.FatalErr(ctx, err, ln.Action("create new route"))
 		}
 
-		fmt.Println(idr.Id)
+		fmt.Println("created route with id " + idr.Id)
+
+		return
 
 	case "route inspect":
 		r, err := rc.Get(context.Background(), &proto.GetRouteRequest{
 			Host: *routesCreateDomain,
 		})
 		if err != nil {
-			ln.Fatal(ln.F{"err": err, "action": "rc.Get"})
+			ln.FatalErr(ctx, err, ln.Action("get single route"), ln.F{"domain": *routesCreateDomain})
 		}
 
 		json.NewEncoder(os.Stdout).Encode(r)
@@ -218,7 +232,7 @@ func main() {
 	case "route list":
 		rts, err := rc.GetAll(context.Background(), &proto.Nil{})
 		if err != nil {
-			ln.Fatal(ln.F{"err": err, "action": "rc.GetAll"})
+			ln.FatalErr(ctx, err, ln.Action("get all routes"))
 		}
 
 		table := tablewriter.NewWriter(os.Stdout)
@@ -235,7 +249,7 @@ func main() {
 	case "route rm":
 		_, err := rc.Delete(context.Background(), &proto.Route{Id: *routesRmID})
 		if err != nil {
-			ln.Fatal(ln.F{"err": err, "action": "rc.Delete"})
+			ln.FatalErr(ctx, err, ln.Action("remove single route"), ln.F{"id": *routesRmID})
 		}
 
 	case "backend list":
@@ -244,7 +258,7 @@ func main() {
 			User:   *backendListUser,
 		})
 		if err != nil {
-			ln.Fatal(ln.F{"err": err, "action": "list backends"})
+			ln.FatalErr(ctx, err, ln.Action("list backends"))
 		}
 
 		table := tablewriter.NewWriter(os.Stdout)
@@ -259,7 +273,7 @@ func main() {
 	case "backend kill":
 		_, err := bc.Kill(context.Background(), &proto.BackendID{Id: *backendKillID})
 		if err != nil {
-			ln.Fatal(ln.F{"err": err, "action": "attempt to kill backend", "backend_id": *backendKillID})
+			ln.FatalErr(ctx, err, ln.Action("attempt to kill backend"), ln.F{"backend_id": *backendKillID})
 		}
 
 		fmt.Println("killed backend " + *backendKillID)
diff --git a/cmd/route-httpagent/main.go b/cmd/route-httpagent/main.go
index f862c19..57ac67b 100644
--- a/cmd/route-httpagent/main.go
+++ b/cmd/route-httpagent/main.go
@@ -1,9 +1,9 @@
 package main
 
 import (
+	"context"
 	"crypto/tls"
 	"flag"
-	"os"
 
 	"git.xeserv.us/xena/route/lib/tun2"
 	"github.com/Xe/ln"
@@ -34,9 +34,6 @@ func main() {
 	client, _ := tun2.NewClient(cfg)
 	err := client.Connect()
 	if err != nil {
-		ln.Error(err, ln.F{
-			"action": "client_running",
-		})
-		os.Exit(1)
+		ln.FatalErr(context.Background(), err, ln.Action("http agent is now running"))
 	}
 }
diff --git a/cmd/routed/main.go b/cmd/routed/main.go
index 56b465e..94c789d 100644
--- a/cmd/routed/main.go
+++ b/cmd/routed/main.go
@@ -1,9 +1,9 @@
 package main
 
 import (
+	"context"
 	"crypto/tls"
 	"flag"
-	"log"
 	"math/rand"
 	"net"
 	"net/http"
@@ -25,26 +25,29 @@ func main() {
 	flag.Parse()
 	flagenv.Parse()
 	rand.Seed(time.Now().Unix())
+	ctx, cancel := context.WithCancel(context.Background())
+	defer cancel()
 
 	certKey, _ := routecrypto.ParseKey(*sslCertKey)
 
 	scfg := server.Config{}
 	err := env.Parse(&scfg)
 	if err != nil {
-		ln.Fatal(ln.F{"err": err, "action": "env.Parse()"})
+		ln.FatalErr(ctx, err, ln.Action("parsing environment for config"))
 	}
 	scfg.CertKey = certKey
 
 	s, err := server.New(scfg)
 	if err != nil {
-		log.Fatal(err)
+		ln.FatalErr(ctx, err, ln.Action("create server instance"))
 	}
 
 	go setupTLS(s, scfg)
 
+	// listen on HTTP listener
 	l, err := net.Listen("tcp", scfg.WebAddr)
 	if err != nil {
-		log.Fatal(err)
+		ln.FatalErr(ctx, err, ln.Action("listening on HTTP port"), ln.F{"addr": scfg.WebAddr})
 	}
 	defer l.Close()
 
@@ -65,5 +68,7 @@ func setupTLS(s *server.Server, scfg server.Config) {
 		},
 	}
 
-	hs.ListenAndServeTLS("", "")
+	for {
+		hs.ListenAndServeTLS("", "")
+	}
 }
diff --git a/internal/database/boltdb.go b/internal/database/boltdb.go
index eec5bfe..c51fb62 100644
--- a/internal/database/boltdb.go
+++ b/internal/database/boltdb.go
@@ -56,7 +56,7 @@ func (b *BoltDBStorage) GetRoute(ctx context.Context, host string) (Route, error
 	r := Route{}
 	err := b.db.One("Hostname", host, &r)
 	if err != nil {
-		ln.Error(err, ln.F{"err": err, "action": "route_get_route"})
+		ln.Error(ctx, err, ln.F{"err": err, "action": "route_get_route"})
 
 		switch err {
 		case storm.ErrNotFound:
diff --git a/internal/server/common.go b/internal/server/common.go
index e55c179..9ba6c26 100644
--- a/internal/server/common.go
+++ b/internal/server/common.go
@@ -49,7 +49,7 @@ func (s *Server) getAuth(ctx context.Context, scope string) (database.Token, err
 }
 
 func handleError(ctx context.Context, clitok database.Token, err error, f ln.F) error {
-	ln.Error(err, f, clitok.F())
+	ln.Error(ctx, err, f, clitok)
 
 	return err
 }
diff --git a/internal/server/route.go b/internal/server/route.go
index 080a34c..08fb2e7 100644
--- a/internal/server/route.go
+++ b/internal/server/route.go
@@ -26,7 +26,7 @@ func (r *Route) Get(ctx context.Context, req *proto.GetRouteRequest) (*proto.Rou
 
 	val, err := r.db.GetRoute(ctx, req.Host)
 	if err != nil {
-		ln.Error(err, ln.F{"action": "Route.Get"})
+		ln.Error(ctx, err, ln.F{"action": "Route.Get"})
 
 		return nil, err
 	}
@@ -47,7 +47,7 @@ func (r *Route) GetAll(ctx context.Context, req *proto.Nil) (*proto.GetAllRoutes
 
 	routes, err := r.db.GetAllRoutes(ctx, clitok.Owner)
 	if err != nil {
-		ln.Error(err, ln.F{"action": "Route.GetAll"})
+		ln.Error(ctx, err, ln.F{"action": "Route.GetAll"})
 
 		return nil, err
 	}
@@ -76,12 +76,12 @@ func (r *Route) Put(ctx context.Context, rt *proto.Route) (*proto.IDResponse, er
 
 	drt, err := r.db.PutRoute(ctx, rt.Host, clitok.Owner)
 	if err != nil {
-		ln.Error(err, ln.F{"action": "Route.Put"})
+		ln.Error(ctx, err, ln.F{"action": "Route.Put"})
 
 		return nil, err
 	}
 
-	ln.Log(drt.F(), ln.F{"action": "Route.Put_success"})
+	ln.Log(ctx, drt, ln.F{"action": "Route.Put_success"})
 
 	return &proto.IDResponse{
 		Id: drt.ID,
@@ -96,7 +96,7 @@ func (r *Route) Delete(ctx context.Context, rt *proto.Route) (*proto.IDResponse,
 
 	drt, err := r.db.GetRoute(ctx, rt.Host)
 	if err != nil {
-		ln.Error(err, ln.F{"action": "Route.Delete_getRoute_verify"})
+		ln.Error(ctx, err, ln.F{"action": "Route.Delete_getRoute_verify"})
 
 		return nil, err
 	}
@@ -112,7 +112,7 @@ func (r *Route) Delete(ctx context.Context, rt *proto.Route) (*proto.IDResponse,
 		handleError(ctx, clitok, ErrNotAuthorized, f)
 	}
 
-	ln.Log(f, drt.F())
+	ln.Log(ctx, f, drt)
 
 	return &proto.IDResponse{Id: rt.Id}, nil
 }
diff --git a/lib/tun2/connection.go b/lib/tun2/connection.go
index cf9fa5d..ae2d646 100644
--- a/lib/tun2/connection.go
+++ b/lib/tun2/connection.go
@@ -50,14 +50,18 @@ func (c *Connection) F() ln.F {
 // Ping ends a "ping" to the client. If the client doesn't respond or the connection
 // dies, then the connection needs to be cleaned up.
 func (c *Connection) Ping() error {
+	ctx, cancel := context.WithTimeout(context.Background(), 1*time.Second)
+	defer cancel()
+
 	req, err := http.NewRequest("GET", "http://backend/health", nil)
 	if err != nil {
 		panic(err)
 	}
+	req = req.WithContext(ctx)
 
 	_, err = c.RoundTrip(req)
 	if err != nil {
-		ln.Error(err, c.F(), ln.F{"action": "ping_roundtrip"})
+		ln.Error(ctx, err, c, ln.Action("pinging the backend"))
 		return err
 	}
 
@@ -67,20 +71,20 @@ func (c *Connection) Ping() error {
 }
 
 // OpenStream creates a new stream (connection) to the backend server.
-func (c *Connection) OpenStream() (net.Conn, error) {
+func (c *Connection) OpenStream(ctx context.Context) (net.Conn, error) {
 	if !c.usable {
 		return nil, ErrNoSuchBackend
 	}
 
 	err := c.conn.SetDeadline(time.Now().Add(time.Second))
 	if err != nil {
-		ln.Error(err, c.F())
+		ln.Error(ctx, err, c)
 		return nil, err
 	}
 
 	stream, err := c.session.OpenStream()
 	if err != nil {
-		ln.Error(err, c.F())
+		ln.Error(ctx, err, c)
 		return nil, err
 	}
 
@@ -117,7 +121,7 @@ var (
 // RoundTrip forwards a HTTP request to the remote backend and then returns the
 // response, if any.
 func (c *Connection) RoundTrip(req *http.Request) (*http.Response, error) {
-	stream, err := c.OpenStream()
+	stream, err := c.OpenStream(req.Context())
 	if err != nil {
 		return nil, errors.Wrap(err, ErrCantOpenSessionStream.Error())
 	}
diff --git a/lib/tun2/server.go b/lib/tun2/server.go
index d191372..3f72373 100644
--- a/lib/tun2/server.go
+++ b/lib/tun2/server.go
@@ -146,7 +146,10 @@ func (s *Server) GetAllBackends() []Backend {
 // ListenAndServe starts the backend TCP/KCP listeners and relays backend
 // traffic to and from them.
 func (s *Server) ListenAndServe() error {
-	ln.Log(ln.F{
+	ctx, cancel := context.WithCancel(context.Background())
+	defer cancel()
+
+	ln.Log(ctx, ln.F{
 		"action": "listen_and_serve_called",
 	})
 
@@ -157,7 +160,7 @@ func (s *Server) ListenAndServe() error {
 				panic(err)
 			}
 
-			ln.Log(ln.F{
+			ln.Log(ctx, ln.F{
 				"action": "tcp+tls_listening",
 				"addr":   l.Addr(),
 			})
@@ -165,11 +168,11 @@ func (s *Server) ListenAndServe() error {
 			for {
 				conn, err := l.Accept()
 				if err != nil {
-					ln.Error(err, ln.F{"kind": "tcp", "addr": l.Addr().String()})
+					ln.Error(ctx, err, ln.F{"kind": "tcp", "addr": l.Addr().String()})
 					continue
 				}
 
-				ln.Log(ln.F{
+				ln.Log(ctx, ln.F{
 					"action": "new_client",
 					"kcp":    false,
 					"addr":   conn.RemoteAddr(),
@@ -187,7 +190,7 @@ func (s *Server) ListenAndServe() error {
 				panic(err)
 			}
 
-			ln.Log(ln.F{
+			ln.Log(ctx, ln.F{
 				"action": "kcp+tls_listening",
 				"addr":   l.Addr(),
 			})
@@ -195,10 +198,10 @@ func (s *Server) ListenAndServe() error {
 			for {
 				conn, err := l.Accept()
 				if err != nil {
-					ln.Error(err, ln.F{"kind": "kcp", "addr": l.Addr().String()})
+					ln.Error(ctx, err, ln.F{"kind": "kcp", "addr": l.Addr().String()})
 				}
 
-				ln.Log(ln.F{
+				ln.Log(ctx, ln.F{
 					"action": "new_client",
 					"kcp":    true,
 					"addr":   conn.RemoteAddr(),
@@ -223,7 +226,7 @@ func (s *Server) ListenAndServe() error {
 				failureChance := c.detector.Phi(now)
 
 				if failureChance > 0.8 {
-					ln.Log(c.F(), ln.F{
+					ln.Log(ctx, c.F(), ln.F{
 						"action": "phi_failure_detection",
 						"value":  failureChance,
 					})
@@ -247,7 +250,7 @@ func (s *Server) HandleConn(c net.Conn, isKCP bool) {
 
 	session, err := smux.Server(c, s.cfg.SmuxConf)
 	if err != nil {
-		ln.Error(err, ln.F{
+		ln.Error(ctx, err, ln.F{
 			"action": "session_failure",
 			"local":  c.LocalAddr().String(),
 			"remote": c.RemoteAddr().String(),
@@ -261,7 +264,7 @@ func (s *Server) HandleConn(c net.Conn, isKCP bool) {
 
 	controlStream, err := session.OpenStream()
 	if err != nil {
-		ln.Error(err, ln.F{
+		ln.Error(ctx, err, ln.F{
 			"action": "control_stream_failure",
 			"local":  c.LocalAddr().String(),
 			"remote": c.RemoteAddr().String(),
@@ -275,7 +278,7 @@ func (s *Server) HandleConn(c net.Conn, isKCP bool) {
 	auth := &Auth{}
 	err = csd.Decode(auth)
 	if err != nil {
-		ln.Error(err, ln.F{
+		ln.Error(ctx, err, ln.F{
 			"action": "control_stream_auth_decoding_failure",
 			"local":  c.LocalAddr().String(),
 			"remote": c.RemoteAddr().String(),
@@ -286,7 +289,7 @@ func (s *Server) HandleConn(c net.Conn, isKCP bool) {
 
 	routeUser, err := s.cfg.Storage.HasRoute(auth.Domain)
 	if err != nil {
-		ln.Error(err, ln.F{
+		ln.Error(ctx, err, ln.F{
 			"action": "nosuch_domain",
 			"local":  c.LocalAddr().String(),
 			"remote": c.RemoteAddr().String(),
@@ -297,7 +300,7 @@ func (s *Server) HandleConn(c net.Conn, isKCP bool) {
 
 	tokenUser, scopes, err := s.cfg.Storage.HasToken(auth.Token)
 	if err != nil {
-		ln.Error(err, ln.F{
+		ln.Error(ctx, err, ln.F{
 			"action": "nosuch_token",
 			"local":  c.LocalAddr().String(),
 			"remote": c.RemoteAddr().String(),
@@ -315,7 +318,7 @@ func (s *Server) HandleConn(c net.Conn, isKCP bool) {
 	}
 
 	if !ok {
-		ln.Error(ErrAuthMismatch, ln.F{
+		ln.Error(ctx, ErrAuthMismatch, ln.F{
 			"action": "token_not_authorized",
 			"local":  c.LocalAddr().String(),
 			"remote": c.RemoteAddr().String(),
@@ -323,7 +326,7 @@ func (s *Server) HandleConn(c net.Conn, isKCP bool) {
 	}
 
 	if routeUser != tokenUser {
-		ln.Error(ErrAuthMismatch, ln.F{
+		ln.Error(ctx, ErrAuthMismatch, ln.F{
 			"action": "auth_mismatch",
 			"local":  c.LocalAddr().String(),
 			"remote": c.RemoteAddr().String(),
@@ -346,11 +349,11 @@ func (s *Server) HandleConn(c net.Conn, isKCP bool) {
 
 	defer func() {
 		if r := recover(); r != nil {
-			ln.Log(connection, ln.F{"action": "connection handler panic", "err": r})
+			ln.Log(ctx, connection, ln.F{"action": "connection handler panic", "err": r})
 		}
 	}()
 
-	ln.Log(ln.F{
+	ln.Log(ctx, ln.F{
 		"action": "backend_connected",
 	}, connection.F())
 
@@ -386,7 +389,7 @@ func (s *Server) HandleConn(c net.Conn, isKCP bool) {
 				connection.cancel()
 			}
 		case <-ctx.Done():
-			s.RemoveConn(connection)
+			s.RemoveConn(ctx, connection)
 			connection.Close()
 
 			return
@@ -395,7 +398,7 @@ func (s *Server) HandleConn(c net.Conn, isKCP bool) {
 }
 
 // RemoveConn removes a connection.
-func (s *Server) RemoveConn(connection *Connection) {
+func (s *Server) RemoveConn(ctx context.Context, connection *Connection) {
 	s.connlock.Lock()
 	delete(s.conns, connection.conn)
 	s.connlock.Unlock()
@@ -408,7 +411,7 @@ func (s *Server) RemoveConn(connection *Connection) {
 	if ok {
 		conns, ok = val.([]*Connection)
 		if !ok {
-			ln.Error(ErrCantRemoveWhatDoesntExist, connection.F(), ln.F{
+			ln.Error(ctx, ErrCantRemoveWhatDoesntExist, connection.F(), ln.F{
 				"action": "looking_up_for_disconnect_removal",
 			})
 			return
@@ -428,7 +431,7 @@ func (s *Server) RemoveConn(connection *Connection) {
 		s.domains.Remove(auth.Domain)
 	}
 
-	ln.Log(connection.F(), ln.F{
+	ln.Log(ctx, connection.F(), ln.F{
 		"action": "client_disconnecting",
 	})
 }
@@ -469,12 +472,13 @@ func gen502Page(req *http.Request) *http.Response {
 // RoundTrip sends a HTTP request to a backend and then returns its response.
 func (s *Server) RoundTrip(req *http.Request) (*http.Response, error) {
 	var conns []*Connection
+	ctx := req.Context()
 
 	val, ok := s.domains.Get(req.Host)
 	if ok {
 		conns, ok = val.([]*Connection)
 		if !ok {
-			ln.Error(ErrNoSuchBackend, ln.F{
+			ln.Error(ctx, ErrNoSuchBackend, ln.F{
 				"action": "no_backend_connected",
 				"remote": req.RemoteAddr,
 				"host":   req.Host,
@@ -493,7 +497,7 @@ func (s *Server) RoundTrip(req *http.Request) (*http.Response, error) {
 	}
 
 	if len(goodConns) == 0 {
-		ln.Error(ErrNoSuchBackend, ln.F{
+		ln.Error(ctx, ErrNoSuchBackend, ln.F{
 			"action": "no_backend_connected",
 			"remote": req.RemoteAddr,
 			"host":   req.Host,
@@ -507,7 +511,7 @@ func (s *Server) RoundTrip(req *http.Request) (*http.Response, error) {
 
 	resp, err := c.RoundTrip(req)
 	if err != nil {
-		ln.Error(err, c.F(), ln.F{
+		ln.Error(ctx, err, c, ln.F{
 			"action": "connection_roundtrip",
 		})
 
@@ -515,7 +519,7 @@ func (s *Server) RoundTrip(req *http.Request) (*http.Response, error) {
 		return nil, err
 	}
 
-	ln.Log(c.F(), ln.F{
+	ln.Log(ctx, c, ln.F{
 		"action":      "http_traffic",
 		"remote_addr": req.RemoteAddr,
 		"host":        req.Host,

From 14fb7f723d88d4936fee4076c3b49c77eb98b202 Mon Sep 17 00:00:00 2001
From: Christine Dodrill <me@christine.website>
Date: Sun, 1 Oct 2017 06:54:56 -0700
Subject: [PATCH 3/5] start adding go stdlib tracing

---
 cmd/routed/main.go                    |  6 ++-
 {cmd/routed => internal}/gops.go      |  2 +-
 internal/init.go                      | 11 +++++
 internal/manhole.go                   | 27 +++++++++++
 internal/middleware/trace.go          | 41 ++++++++++++++++
 vendor-log                            |  5 ++
 vendor/github.com/Xe/ln/ex/doc.go     |  7 +++
 vendor/github.com/Xe/ln/ex/gotrace.go | 68 +++++++++++++++++++++++++++
 vendor/github.com/Xe/ln/ex/http.go    | 36 ++++++++++++++
 vendor/github.com/Xe/ln/ex/l2met.go   | 25 ++++++++++
 10 files changed, 225 insertions(+), 3 deletions(-)
 rename {cmd/routed => internal}/gops.go (88%)
 create mode 100644 internal/init.go
 create mode 100644 internal/manhole.go
 create mode 100644 internal/middleware/trace.go
 create mode 100644 vendor/github.com/Xe/ln/ex/doc.go
 create mode 100644 vendor/github.com/Xe/ln/ex/gotrace.go
 create mode 100644 vendor/github.com/Xe/ln/ex/http.go
 create mode 100644 vendor/github.com/Xe/ln/ex/l2met.go

diff --git a/cmd/routed/main.go b/cmd/routed/main.go
index 94c789d..2899bb4 100644
--- a/cmd/routed/main.go
+++ b/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,
diff --git a/cmd/routed/gops.go b/internal/gops.go
similarity index 88%
rename from cmd/routed/gops.go
rename to internal/gops.go
index 184b656..51620fc 100644
--- a/cmd/routed/gops.go
+++ b/internal/gops.go
@@ -1,4 +1,4 @@
-package main
+package internal
 
 import (
 	"log"
diff --git a/internal/init.go b/internal/init.go
new file mode 100644
index 0000000..f9cb251
--- /dev/null
+++ b/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())
+}
diff --git a/internal/manhole.go b/internal/manhole.go
new file mode 100644
index 0000000..9de919b
--- /dev/null
+++ b/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)
+}
diff --git a/internal/middleware/trace.go b/internal/middleware/trace.go
new file mode 100644
index 0000000..3db56c1
--- /dev/null
+++ b/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)
+	})
+}
diff --git a/vendor-log b/vendor-log
index 6495569..f67b125 100644
--- a/vendor-log
+++ b/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
diff --git a/vendor/github.com/Xe/ln/ex/doc.go b/vendor/github.com/Xe/ln/ex/doc.go
new file mode 100644
index 0000000..932ed42
--- /dev/null
+++ b/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
diff --git a/vendor/github.com/Xe/ln/ex/gotrace.go b/vendor/github.com/Xe/ln/ex/gotrace.go
new file mode 100644
index 0000000..5579879
--- /dev/null
+++ b/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)
+}
diff --git a/vendor/github.com/Xe/ln/ex/http.go b/vendor/github.com/Xe/ln/ex/http.go
new file mode 100644
index 0000000..c5715a3
--- /dev/null
+++ b/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)
+	})
+}
diff --git a/vendor/github.com/Xe/ln/ex/l2met.go b/vendor/github.com/Xe/ln/ex/l2met.go
new file mode 100644
index 0000000..e2a7f19
--- /dev/null
+++ b/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)}
+}

From e1ce5dfd539eba5affff2fd54c8c2187aa6df5c8 Mon Sep 17 00:00:00 2001
From: Christine Dodrill <me@christine.website>
Date: Sun, 1 Oct 2017 07:37:47 -0700
Subject: [PATCH 4/5] cmd/route-cli: implement some token management commands

---
 cmd/route-cli/main.go | 46 +++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 46 insertions(+)

diff --git a/cmd/route-cli/main.go b/cmd/route-cli/main.go
index 9d1b87f..42fadc5 100644
--- a/cmd/route-cli/main.go
+++ b/cmd/route-cli/main.go
@@ -148,6 +148,8 @@ retry_netrc:
 
 		ln.FatalErr(ctx, http.ListenAndServe(*testServerAddr, nil), ln.Action("test server listenAndServe"))
 
+		return
+
 	case "generate-key":
 		key, err := routecrypto.GenerateKey()
 		if err != nil {
@@ -155,6 +157,9 @@ retry_netrc:
 		}
 
 		fmt.Println("Your key is:", routecrypto.ShowKey(key))
+
+		return
+
 	case "token generate-root":
 		key, err := routecrypto.ParseKey(*tokenGenerateKey)
 		if err != nil {
@@ -252,6 +257,8 @@ retry_netrc:
 			ln.FatalErr(ctx, err, ln.Action("remove single route"), ln.F{"id": *routesRmID})
 		}
 
+		return
+
 	case "backend list":
 		bkds, err := bc.List(context.Background(), &proto.BackendSelector{
 			Domain: *backendListDomain,
@@ -270,6 +277,8 @@ retry_netrc:
 
 		table.Render()
 
+		return
+
 	case "backend kill":
 		_, err := bc.Kill(context.Background(), &proto.BackendID{Id: *backendKillID})
 		if err != nil {
@@ -277,5 +286,42 @@ retry_netrc:
 		}
 
 		fmt.Println("killed backend " + *backendKillID)
+
+		return
+
+	case "token list":
+		lis, err := tc.GetAll(ctx, &proto.Nil{})
+		if err != nil {
+			ln.FatalErr(ctx, err, ln.Action("get all tokens"))
+		}
+
+		table := tablewriter.NewWriter(os.Stdout)
+		table.SetHeader([]string{"ID", "Active", "Scopes"})
+
+		for _, tkn := range lis.Tokens {
+			table.Append([]string{tkn.Id, fmt.Sprint(tkn.Active), fmt.Sprint(tkn.Scopes)})
+		}
+
+		table.Render()
+
+		return
+
+	case "token create":
+		scps := *tokenCreateScopes
+		tkn := &proto.Token{
+			Scopes: scps,
+		}
+
+		ftkn, err := tc.Put(ctx, tkn)
+		if err != nil {
+			ln.FatalErr(ctx, err, ln.Action("put token to server"))
+		}
+
+		fmt.Printf("Your token is: %s\n", ftkn.Body)
+		fmt.Printf("It has permission for the following scopes: %v\n", ftkn.Scopes)
+
+		return
 	}
+
+	ln.Fatal(ctx, ln.Action("not implemented"), ln.F{"command": cmdline})
 }

From dc40bfa5baa68133b7ded1c103abde7f784cf332 Mon Sep 17 00:00:00 2001
From: Christine Dodrill <me@christine.website>
Date: Sun, 1 Oct 2017 08:06:27 -0700
Subject: [PATCH 5/5] internal/server: add grpc tracing

---
 internal/server/backend.go | 24 ++++++++++++++++++--
 internal/server/common.go  | 23 ++++++++++++++-----
 internal/server/route.go   | 44 ++++++++++++++++++++----------------
 internal/server/token.go   | 46 ++++++++++++++++++++++++++++----------
 4 files changed, 98 insertions(+), 39 deletions(-)

diff --git a/internal/server/backend.go b/internal/server/backend.go
index 95f4911..88204e5 100644
--- a/internal/server/backend.go
+++ b/internal/server/backend.go
@@ -3,7 +3,9 @@ package server
 import (
 	"git.xeserv.us/xena/route/lib/tun2"
 	proto "git.xeserv.us/xena/route/proto"
+	"github.com/Xe/ln"
 	"golang.org/x/net/context"
+	"golang.org/x/net/trace"
 )
 
 // Backend implements proto.BackendsServer for gRPC.
@@ -13,6 +15,14 @@ type Backend struct {
 
 // List returns a list of backends given filtering parameters.
 func (b *Backend) List(ctx context.Context, sel *proto.BackendSelector) (*proto.BackendList, error) {
+	ctx, clitok, err := b.getAuth(ctx, "backend list", "backend:list")
+	if err != nil {
+		return nil, handleError(ctx, clitok, err, ln.F{"action": "authentication for backend list"})
+	}
+
+	tr, _ := trace.FromContext(ctx)
+	defer tr.Finish()
+
 	bl := map[string]tun2.Backend{}
 
 	switch {
@@ -51,9 +61,19 @@ func (b *Backend) List(ctx context.Context, sel *proto.BackendSelector) (*proto.
 
 // Kill removes a backend's connection by ID.
 func (b *Backend) Kill(ctx context.Context, bid *proto.BackendID) (*proto.Nil, error) {
-	if err := b.ts.KillBackend(bid.Id); err != nil {
-		return nil, err
+	ctx, clitok, err := b.getAuth(ctx, "backend list", "backend:list")
+	if err != nil {
+		return nil, handleError(ctx, clitok, err, ln.F{"action": "authentication for backend list"})
 	}
 
+	tr, _ := trace.FromContext(ctx)
+	defer tr.Finish()
+
+	if err := b.ts.KillBackend(bid.Id); err != nil {
+		return nil, handleError(ctx, clitok, err, ln.F{"action": "killing backend", "backend_id": bid.Id})
+	}
+
+	ln.Log(ctx, clitok, ln.Action("backend killed"), ln.F{"backend_id": bid.Id})
+
 	return &proto.Nil{}, nil
 }
diff --git a/internal/server/common.go b/internal/server/common.go
index 9ba6c26..faab359 100644
--- a/internal/server/common.go
+++ b/internal/server/common.go
@@ -6,6 +6,7 @@ import (
 
 	"git.xeserv.us/xena/route/internal/database"
 	"github.com/Xe/ln"
+	"golang.org/x/net/trace"
 	"google.golang.org/grpc"
 	"google.golang.org/grpc/codes"
 	"google.golang.org/grpc/metadata"
@@ -16,23 +17,23 @@ var (
 	ErrNotAuthorized = errors.New("server: not authorized")
 )
 
-func (s *Server) getAuth(ctx context.Context, scope string) (database.Token, error) {
+func (s *Server) getAuth(ctx context.Context, operation, scope string) (context.Context, database.Token, error) {
 	var err error
 
 	md, ok := metadata.FromIncomingContext(ctx)
 	if !ok {
-		return database.Token{}, grpc.Errorf(codes.Unauthenticated, "valid token required.")
+		return nil, database.Token{}, grpc.Errorf(codes.Unauthenticated, "valid token required.")
 	}
 
 	jwtToken, ok := md["authorization"]
 	if !ok {
-		return database.Token{}, grpc.Errorf(codes.Unauthenticated, "valid token required.")
+		return nil, database.Token{}, grpc.Errorf(codes.Unauthenticated, "valid token required.")
 	}
 	val := jwtToken[0]
 
 	t, err := s.db.GetToken(ctx, val)
 	if err != nil {
-		return database.Token{}, grpc.Errorf(codes.Unauthenticated, "valid token required.")
+		return nil, database.Token{}, grpc.Errorf(codes.Unauthenticated, "valid token required.")
 	}
 
 	ok = false
@@ -42,13 +43,23 @@ func (s *Server) getAuth(ctx context.Context, scope string) (database.Token, err
 		}
 	}
 	if !ok {
-		return database.Token{}, grpc.Errorf(codes.Unauthenticated, "invalid scope.")
+		return nil, database.Token{}, grpc.Errorf(codes.Unauthenticated, "invalid scope.")
 	}
 
-	return t, nil
+	tr := trace.New("routed-grpc", operation)
+	ctx = trace.NewContext(ctx, tr)
+
+	return ctx, t, nil
 }
 
 func handleError(ctx context.Context, clitok database.Token, err error, f ln.F) error {
+	tr, ok := trace.FromContext(ctx)
+	if !ok {
+		goto skip
+	}
+	tr.SetError()
+
+skip:
 	ln.Error(ctx, err, f, clitok)
 
 	return err
diff --git a/internal/server/route.go b/internal/server/route.go
index 08fb2e7..7f5a28c 100644
--- a/internal/server/route.go
+++ b/internal/server/route.go
@@ -5,6 +5,7 @@ import (
 	proto "git.xeserv.us/xena/route/proto"
 	"github.com/Xe/ln"
 	"golang.org/x/net/context"
+	"golang.org/x/net/trace"
 )
 
 // Route implements rout.RoutesServer for gRPC
@@ -19,16 +20,17 @@ var (
 
 // Get fetches a route from the database.
 func (r *Route) Get(ctx context.Context, req *proto.GetRouteRequest) (*proto.Route, error) {
-	clitok, err := r.getAuth(ctx, "route:get")
+	ctx, clitok, err := r.getAuth(ctx, "get single route", "route:get")
 	if err != nil {
 		return nil, handleError(ctx, clitok, err, ln.F{"action": "Route.Get_getAuth"})
 	}
 
+	tr, _ := trace.FromContext(ctx)
+	defer tr.Finish()
+
 	val, err := r.db.GetRoute(ctx, req.Host)
 	if err != nil {
-		ln.Error(ctx, err, ln.F{"action": "Route.Get"})
-
-		return nil, err
+		return nil, handleError(ctx, clitok, err, ln.F{"action": "get single route from database", "host": req.Host})
 	}
 
 	if val.Creator != clitok.Owner {
@@ -40,16 +42,17 @@ func (r *Route) Get(ctx context.Context, req *proto.GetRouteRequest) (*proto.Rou
 
 // GetAll fetches all of the routes that you own.
 func (r *Route) GetAll(ctx context.Context, req *proto.Nil) (*proto.GetAllRoutesResponse, error) {
-	clitok, err := r.getAuth(ctx, "route:getall")
+	ctx, clitok, err := r.getAuth(ctx, "get all routes for user", "route:getall")
 	if err != nil {
 		return nil, handleError(ctx, clitok, err, ln.F{"action": "Route.GetAll_getAuth"})
 	}
 
+	tr, _ := trace.FromContext(ctx)
+	defer tr.Finish()
+
 	routes, err := r.db.GetAllRoutes(ctx, clitok.Owner)
 	if err != nil {
-		ln.Error(ctx, err, ln.F{"action": "Route.GetAll"})
-
-		return nil, err
+		return nil, handleError(ctx, clitok, err, ln.F{"action": "get all routes for user from database"})
 	}
 
 	result := []*proto.Route{}
@@ -65,23 +68,24 @@ func (r *Route) GetAll(ctx context.Context, req *proto.Nil) (*proto.GetAllRoutes
 }
 
 func (r *Route) Put(ctx context.Context, rt *proto.Route) (*proto.IDResponse, error) {
-	clitok, err := r.getAuth(ctx, "route:put")
+	ctx, clitok, err := r.getAuth(ctx, "put new route", "route:put")
 	if err != nil {
 		return nil, handleError(ctx, clitok, err, ln.F{"action": "Route.Put_getAuth"})
 	}
 
+	tr, _ := trace.FromContext(ctx)
+	defer tr.Finish()
+
 	if rt.Host == "" {
 		rt.Host = elfs.MakeName() + r.cfg.DomainSuffix
 	}
 
 	drt, err := r.db.PutRoute(ctx, rt.Host, clitok.Owner)
 	if err != nil {
-		ln.Error(ctx, err, ln.F{"action": "Route.Put"})
-
-		return nil, err
+		return nil, handleError(ctx, clitok, err, ln.F{"action": "put route to database"})
 	}
 
-	ln.Log(ctx, drt, ln.F{"action": "Route.Put_success"})
+	ln.Log(ctx, drt, ln.Action("created new route"))
 
 	return &proto.IDResponse{
 		Id: drt.ID,
@@ -89,29 +93,31 @@ func (r *Route) Put(ctx context.Context, rt *proto.Route) (*proto.IDResponse, er
 }
 
 func (r *Route) Delete(ctx context.Context, rt *proto.Route) (*proto.IDResponse, error) {
-	clitok, err := r.getAuth(ctx, "route:delete")
+	ctx, clitok, err := r.getAuth(ctx, "delete single route", "route:delete")
 	if err != nil {
 		return nil, handleError(ctx, clitok, err, ln.F{"action": "Route.Delete_getAuth"})
 	}
 
+	tr, _ := trace.FromContext(ctx)
+	defer tr.Finish()
+
 	drt, err := r.db.GetRoute(ctx, rt.Host)
 	if err != nil {
-		ln.Error(ctx, err, ln.F{"action": "Route.Delete_getRoute_verify"})
-
-		return nil, err
+		return nil, handleError(ctx, clitok, err, ln.F{"action": "fetch route from database", "host": rt.Host})
 	}
 
 	if drt.Creator != clitok.Owner {
-		return nil, handleError(ctx, clitok, ErrNotAuthorized, ln.F{"action": "Route.Delete_not_authorized"})
+		return nil, handleError(ctx, clitok, ErrNotAuthorized, ln.F{"action": "user not authorized to delete this route", "host": rt.Host})
 	}
 
 	err = r.db.DeleteRoute(ctx, rt.Id)
 	f := drt.F()
-	f["action"] = "Route.Delete_db.DeleteRoute"
+	f["action"] = "delete route from database"
 	if err != nil {
 		handleError(ctx, clitok, ErrNotAuthorized, f)
 	}
 
+	f["action"] = "deleted route from database"
 	ln.Log(ctx, f, drt)
 
 	return &proto.IDResponse{Id: rt.Id}, nil
diff --git a/internal/server/token.go b/internal/server/token.go
index 8d42b41..1f49431 100644
--- a/internal/server/token.go
+++ b/internal/server/token.go
@@ -5,6 +5,7 @@ import (
 	"github.com/Xe/ln"
 	"github.com/Xe/uuid"
 	"golang.org/x/net/context"
+	"golang.org/x/net/trace"
 	"google.golang.org/grpc/codes"
 	"google.golang.org/grpc/status"
 )
@@ -20,11 +21,14 @@ var (
 )
 
 func (t *Token) Get(ctx context.Context, req *proto.GetTokenRequest) (*proto.Token, error) {
-	clitok, err := t.getAuth(ctx, "token:get")
+	ctx, clitok, err := t.getAuth(ctx, "get single token", "token:get")
 	if err != nil {
-		return nil, handleError(ctx, clitok, err, ln.F{"action": "Token.Get_getAuth"})
+		return nil, handleError(ctx, clitok, err, ln.F{"action": "not authorized"})
 	}
 
+	tr, _ := trace.FromContext(ctx)
+	defer tr.Finish()
+
 	if req.Id == "" {
 		return nil, status.Errorf(codes.InvalidArgument, "must specify ID")
 	}
@@ -42,11 +46,14 @@ func (t *Token) Get(ctx context.Context, req *proto.GetTokenRequest) (*proto.Tok
 }
 
 func (t *Token) GetAll(ctx context.Context, req *proto.Nil) (*proto.TokenSet, error) {
-	clitok, err := t.getAuth(ctx, "token:getall")
+	ctx, clitok, err := t.getAuth(ctx, "get all tokens", "token:getall")
 	if err != nil {
 		return nil, handleError(ctx, clitok, err, ln.F{"action": "Token.GetAll_getAuth"})
 	}
 
+	tr, _ := trace.FromContext(ctx)
+	defer tr.Finish()
+
 	toks, err := t.db.GetTokensForOwner(ctx, clitok.Owner)
 	if err != nil {
 		return nil, handleError(ctx, clitok, err, ln.F{"action": "Token.GetAll_db.GetTokensForOwner"})
@@ -64,43 +71,58 @@ func (t *Token) GetAll(ctx context.Context, req *proto.Nil) (*proto.TokenSet, er
 }
 
 func (t *Token) Put(ctx context.Context, tok *proto.Token) (*proto.Token, error) {
-	clitok, err := t.getAuth(ctx, "token:put")
+	ctx, clitok, err := t.getAuth(ctx, "put new token", "token:put")
 	if err != nil {
-		return nil, handleError(ctx, clitok, err, ln.F{"action": "Token.Put_getAuth"})
+		return nil, handleError(ctx, clitok, err, ln.F{"action": "not authorized"})
 	}
 
+	tr, _ := trace.FromContext(ctx)
+	defer tr.Finish()
+
 	dbt, err := t.db.PutToken(ctx, uuid.New(), clitok.Owner, tok.Scopes)
 	if err != nil {
-		return nil, handleError(ctx, clitok, err, ln.F{"action": "Token.Put_db.PutToken"})
+		return nil, handleError(ctx, clitok, err, ln.F{"action": "put token into database", "scopes": tok.Scopes})
 	}
 
+	ln.Log(ctx, dbt, ln.Action("new token created"))
+
 	return dbt.AsProto(), nil
 }
 
 func (t *Token) Delete(ctx context.Context, tok *proto.Token) (*proto.Nil, error) {
-	clitok, err := t.getAuth(ctx, "token:delete")
+	ctx, clitok, err := t.getAuth(ctx, "delete single token", "token:delete")
 	if err != nil {
-		return nil, handleError(ctx, clitok, err, ln.F{"action": "Token.Delete_getAuth"})
+		return nil, handleError(ctx, clitok, err, ln.F{"action": "not authorized"})
 	}
 
+	tr, _ := trace.FromContext(ctx)
+	defer tr.Finish()
+
 	err = t.db.DeleteToken(ctx, tok.Id)
 	if err != nil {
-		return nil, handleError(ctx, clitok, err, ln.F{"action": "Token.Delete_db.DeleteToken"})
+		return nil, handleError(ctx, clitok, err, ln.F{"action": "delete token from database", "token_id": tok.Id})
 	}
 
+	ln.Log(ctx, clitok, ln.Action("token deleted"), ln.F{"token_id": tok.Id})
+
 	return &proto.Nil{}, nil
 }
 
 func (t *Token) Deactivate(ctx context.Context, tok *proto.Token) (*proto.Nil, error) {
-	clitok, err := t.getAuth(ctx, "token:deactivate")
+	ctx, clitok, err := t.getAuth(ctx, "deactivate single token", "token:deactivate")
 	if err != nil {
-		return nil, handleError(ctx, clitok, err, ln.F{"action": "Token.Deactivate_getAuth"})
+		return nil, handleError(ctx, clitok, err, ln.F{"action": "not authorized"})
 	}
 
+	tr, _ := trace.FromContext(ctx)
+	defer tr.Finish()
+
 	err = t.db.DeactivateToken(ctx, tok.Id)
 	if err != nil {
-		return nil, handleError(ctx, clitok, err, ln.F{"action": "Token.Deactivate_db.DeactivateToken"})
+		return nil, handleError(ctx, clitok, err, ln.F{"action": "deactivate token in database", "token_id": tok.Id})
 	}
 
+	ln.Log(ctx, clitok, ln.Action("deactivated token"), ln.F{"token_id": tok.Id})
+
 	return &proto.Nil{}, nil
 }