internal/server: add grpc tracing

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 {
+	ctx, clitok, err := b.getAuth(ctx, "backend list", "backend:list")
-		return nil, err
+	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
 }

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

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, handleError(ctx, clitok, err, ln.F{"action": "get single route from database", "host": req.Host})
-
-		return nil, err
 	}
 
 	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, handleError(ctx, clitok, err, ln.F{"action": "get all routes for user from database"})
-
-		return nil, err
 	}
 
 	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, handleError(ctx, clitok, err, ln.F{"action": "put route to database"})
-
-		return nil, err
 	}
 
-	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, handleError(ctx, clitok, err, ln.F{"action": "fetch route from database", "host": rt.Host})
-
-		return nil, err
 	}
 
 	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

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
 }