add tracing to namesys and pathresolver

- partially addresses #5783

License: MIT
Signed-off-by: frrist <forrest.weston@gmail.com>

core/pathresolver.go

@@ -10,7 +10,6 @@ import (
 	path "gx/ipfs/QmVi2uUygezqaMTqs3Yzt5FcZFHJoYD4B7jQ2BELjj7ZuY/go-path"
 	resolver "gx/ipfs/QmVi2uUygezqaMTqs3Yzt5FcZFHJoYD4B7jQ2BELjj7ZuY/go-path/resolver"
 	ipld "gx/ipfs/QmcKKBwfz6FyQdHR2jsXrrF6XeSBXYL86anmWNewpFpoF5/go-ipld-format"
-	logging "gx/ipfs/QmcuXC5cxs79ro2cUuHs4HQ2bkDLJUYokwL8aivcX6HW3C/go-log"
 )
 
 // ErrNoNamesys is an explicit error for when an IPFS node doesn't
@@ -19,42 +18,37 @@ var ErrNoNamesys = errors.New(
 	"core/resolve: no Namesys on IpfsNode - can't resolve ipns entry")
 
 // ResolveIPNS resolves /ipns paths
-func ResolveIPNS(ctx context.Context, nsys namesys.NameSystem, p path.Path) (path.Path, error) {
+func ResolveIPNS(ctx context.Context, nsys namesys.NameSystem, p path.Path) (out path.Path, err error) {
+	ctx = log.Start(ctx, "ResolveIPNS")
+	defer func() { log.FinishWithErr(ctx, err) }()
 	if strings.HasPrefix(p.String(), "/ipns/") {
-		evt := log.EventBegin(ctx, "resolveIpnsPath")
-		defer evt.Done()
 		// resolve ipns paths
 
 		// TODO(cryptix): we should be able to query the local cache for the path
 		if nsys == nil {
-			evt.Append(logging.LoggableMap{"error": ErrNoNamesys.Error()})
 			return "", ErrNoNamesys
 		}
 
 		seg := p.Segments()
 
 		if len(seg) < 2 || seg[1] == "" { // just "/<protocol/>" without further segments
-			evt.Append(logging.LoggableMap{"error": path.ErrNoComponents.Error()})
 			return "", path.ErrNoComponents
 		}
 
 		extensions := seg[2:]
 		resolvable, err := path.FromSegments("/", seg[0], seg[1])
 		if err != nil {
-			evt.Append(logging.LoggableMap{"error": err.Error()})
 			return "", err
 		}
 
 		respath, err := nsys.Resolve(ctx, resolvable.String())
 		if err != nil {
-			evt.Append(logging.LoggableMap{"error": err.Error()})
 			return "", err
 		}
 
 		segments := append(respath.Segments(), extensions...)
 		p, err = path.FromSegments("/", segments...)
 		if err != nil {
-			evt.Append(logging.LoggableMap{"error": err.Error()})
 			return "", err
 		}
 	}
@@ -64,8 +58,11 @@ func ResolveIPNS(ctx context.Context, nsys namesys.NameSystem, p path.Path) (pat
 // Resolve resolves the given path by parsing out protocol-specific
 // entries (e.g. /ipns/<node-key>) and then going through the /ipfs/
 // entries and returning the final node.
-func Resolve(ctx context.Context, nsys namesys.NameSystem, r *resolver.Resolver, p path.Path) (ipld.Node, error) {
-	p, err := ResolveIPNS(ctx, nsys, p)
+func Resolve(ctx context.Context, nsys namesys.NameSystem, r *resolver.Resolver, p path.Path) (out ipld.Node, err error) {
+	ctx = log.Start(ctx, "Resolve")
+	log.SetTag(ctx, "path", p.String())
+	defer func() { log.FinishWithErr(ctx, err) }()
+	p, err = ResolveIPNS(ctx, nsys, p)
 	if err != nil {
 		return nil, err
 	}

namesys/base.go

@@ -21,11 +21,14 @@ type resolver interface {
 }
 
 // resolve is a helper for implementing Resolver.ResolveN using resolveOnce.
-func resolve(ctx context.Context, r resolver, name string, options opts.ResolveOpts) (path.Path, error) {
+func resolve(ctx context.Context, r resolver, name string, options opts.ResolveOpts) (out path.Path, err error) {
+	ctx = log.Start(ctx, "resolve")
+	defer func() { log.FinishWithErr(ctx, err) }()
+
 	ctx, cancel := context.WithCancel(ctx)
 	defer cancel()
 
-	err := ErrResolveFailed
+	err = ErrResolveFailed
 	var p path.Path
 
 	resCh := resolveAsync(ctx, r, name, options)
@@ -41,6 +44,7 @@ func resolve(ctx context.Context, r resolver, name string, options opts.ResolveO
 }
 
 func resolveAsync(ctx context.Context, r resolver, name string, options opts.ResolveOpts) <-chan Result {
+	ctx = log.Start(ctx, "resolveAsync")
 	resCh := r.resolveOnceAsync(ctx, name, options)
 	depth := options.Depth
 	outCh := make(chan Result, 1)
@@ -53,6 +57,7 @@ func resolveAsync(ctx context.Context, r resolver, name string, options opts.Res
 			if cancelSub != nil {
 				cancelSub()
 			}
+			log.Finish(ctx)
 		}()
 
 		for {

namesys/dns.go

@@ -69,8 +69,12 @@ func (r *DNSResolver) resolveOnceAsync(ctx context.Context, name string, options
 		return p, nil
 	}
 
+	ctx = log.Start(ctx, "resolveOnceAsync")
 	go func() {
-		defer close(out)
+		defer func() {
+			close(out)
+			log.Finish(ctx)
+		}()
 		for {
 			select {
 			case subRes, ok := <-subChan:

namesys/namesys.go

@@ -127,10 +127,14 @@ func (ns *mpns) resolveOnceAsync(ctx context.Context, name string, options opts.
 		res = ns.proquintResolver
 	}
 
+	ctx = log.Start(ctx, "resolveOnceAsync")
 	resCh := res.resolveOnceAsync(ctx, key, options)
 	var best onceResult
 	go func() {
-		defer close(out)
+		defer func() {
+			close(out)
+			log.Finish(ctx)
+		}()
 		for {
 			select {
 			case res, ok := <-resCh:

namesys/routing.go

@@ -98,9 +98,13 @@ func (r *IpnsResolver) resolveOnceAsync(ctx context.Context, name string, option
 		return out
 	}
 
+	ctx = log.Start(ctx, "resolveOnceAsync")
 	go func() {
-		defer cancel()
-		defer close(out)
+		defer func() {
+			log.Finish(ctx)
+			cancel()
+			close(out)
+		}()
 		for {
 			select {
 			case val, ok := <-vals: