From 846c04b131d7ef9557bcaf80359af4b7b46102c1 Mon Sep 17 00:00:00 2001 From: Forrest Weston Date: Tue, 14 Nov 2017 17:33:11 -0800 Subject: [PATCH 1/3] Added uuid loggable (requestId) to root context Every log event resulting from a command will have a uuid associated with it License: MIT Signed-off-by: Forrest Weston --- commands/http/handler.go | 2 ++ 1 file changed, 2 insertions(+) diff --git a/commands/http/handler.go b/commands/http/handler.go index ec40d1367..bc0f3c594 100644 --- a/commands/http/handler.go +++ b/commands/http/handler.go @@ -17,6 +17,7 @@ import ( cors "gx/ipfs/QmPG2kW5t27LuHgHnvhUwbHCNHAt2eUcb4gPHqofrESUdB/cors" logging "gx/ipfs/QmSpJByNKFX1sCsHBEp3R73FL4NF6FnQTEGyNAXHm2GS52/go-log" + loggables "gx/ipfs/QmT4PgCNdv73hnFAqzHqwW44q7M9PWpykSswHDxndquZbc/go-libp2p-loggables" ) var log = logging.Logger("commands/http") @@ -137,6 +138,7 @@ func (i internalHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { } ctx, cancel := context.WithCancel(node.Context()) + ctx = logging.ContextWithLoggable(ctx, loggables.Uuid("requestId")) defer cancel() if cn, ok := w.(http.CloseNotifier); ok { clientGone := cn.CloseNotify() From 1c3e590c886297ce8bd1649336a7c869acd4c760 Mon Sep 17 00:00:00 2001 From: Forrest Weston Date: Tue, 14 Nov 2017 17:39:30 -0800 Subject: [PATCH 2/3] Add event logging around path resolution License: MIT Signed-off-by: Forrest Weston --- core/pathresolver.go | 1 + path/resolver.go | 2 ++ 2 files changed, 3 insertions(+) diff --git a/core/pathresolver.go b/core/pathresolver.go index fb5b299e0..10223579a 100644 --- a/core/pathresolver.go +++ b/core/pathresolver.go @@ -22,6 +22,7 @@ var ErrNoNamesys = errors.New( // entries and returning the final node. func Resolve(ctx context.Context, nsys namesys.NameSystem, r *path.Resolver, p path.Path) (node.Node, error) { if strings.HasPrefix(p.String(), "/ipns/") { + defer log.EventBegin(ctx, "resolveIpnsPath").Done() // resolve ipns paths // TODO(cryptix): we sould be able to query the local cache for the path diff --git a/path/resolver.go b/path/resolver.go index 5b8fe515a..e11c2767d 100644 --- a/path/resolver.go +++ b/path/resolver.go @@ -135,6 +135,7 @@ func (s *Resolver) ResolvePathComponents(ctx context.Context, fpath Path) ([]nod if err != nil { return nil, err } + defer log.EventBegin(ctx, "resolvePathComponents", logging.LoggableMap{"parts": parts, "cid": h}).Done() log.Debug("resolve dag get") nd, err := s.DAG.Get(ctx, h) @@ -154,6 +155,7 @@ func (s *Resolver) ResolvePathComponents(ctx context.Context, fpath Path) ([]nod // would retrieve "baz" in ("bar" in ("foo" in nd.Links).Links).Links func (s *Resolver) ResolveLinks(ctx context.Context, ndd node.Node, names []string) ([]node.Node, error) { + defer log.EventBegin(ctx, "resolveLinks", logging.LoggableMap{"names": names}).Done() result := make([]node.Node, 0, len(names)+1) result = append(result, ndd) nd := ndd // dup arg workaround From f44cf0034231e075cfe9e8a396a57a5bc4126460 Mon Sep 17 00:00:00 2001 From: Forrest Weston Date: Wed, 15 Nov 2017 12:21:08 -0800 Subject: [PATCH 3/3] Add error message to event logs in path resolution If an error occurs during an event add it to the events metadata License: MIT Signed-off-by: Forrest Weston --- commands/http/handler.go | 2 +- core/pathresolver.go | 9 ++++++++- path/resolver.go | 12 ++++++++++-- 3 files changed, 19 insertions(+), 4 deletions(-) diff --git a/commands/http/handler.go b/commands/http/handler.go index bc0f3c594..dc42a50c5 100644 --- a/commands/http/handler.go +++ b/commands/http/handler.go @@ -138,8 +138,8 @@ func (i internalHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { } ctx, cancel := context.WithCancel(node.Context()) - ctx = logging.ContextWithLoggable(ctx, loggables.Uuid("requestId")) defer cancel() + ctx = logging.ContextWithLoggable(ctx, loggables.Uuid("requestId")) if cn, ok := w.(http.CloseNotifier); ok { clientGone := cn.CloseNotify() go func() { diff --git a/core/pathresolver.go b/core/pathresolver.go index 10223579a..6939a234c 100644 --- a/core/pathresolver.go +++ b/core/pathresolver.go @@ -10,6 +10,7 @@ import ( cid "gx/ipfs/QmNp85zy9RLrQ5oQD4hPyS39ezrrXpcaa7R4Y9kxdWQLLQ/go-cid" node "gx/ipfs/QmPN7cwmpcc4DWXb4KTB9dNAJgjuPY69h3npsMfhRrQL9c/go-ipld-format" + logging "gx/ipfs/QmSpJByNKFX1sCsHBEp3R73FL4NF6FnQTEGyNAXHm2GS52/go-log" ) // ErrNoNamesys is an explicit error for when an IPFS node doesn't @@ -22,34 +23,40 @@ var ErrNoNamesys = errors.New( // entries and returning the final node. func Resolve(ctx context.Context, nsys namesys.NameSystem, r *path.Resolver, p path.Path) (node.Node, error) { if strings.HasPrefix(p.String(), "/ipns/") { - defer log.EventBegin(ctx, "resolveIpnsPath").Done() + evt := log.EventBegin(ctx, "resolveIpnsPath") + defer evt.Done() // resolve ipns paths // TODO(cryptix): we sould be able to query the local cache for the path if nsys == nil { + evt.Append(logging.LoggableMap{"error": ErrNoNamesys.Error()}) return nil, ErrNoNamesys } seg := p.Segments() if len(seg) < 2 || seg[1] == "" { // just "/" without further segments + evt.Append(logging.LoggableMap{"error": path.ErrNoComponents.Error()}) return nil, path.ErrNoComponents } extensions := seg[2:] resolvable, err := path.FromSegments("/", seg[0], seg[1]) if err != nil { + evt.Append(logging.LoggableMap{"error": err.Error()}) return nil, err } respath, err := nsys.Resolve(ctx, resolvable.String()) if err != nil { + evt.Append(logging.LoggableMap{"error": err.Error()}) return nil, err } segments := append(respath.Segments(), extensions...) p, err = path.FromSegments("/", segments...) if err != nil { + evt.Append(logging.LoggableMap{"error": err.Error()}) return nil, err } } diff --git a/path/resolver.go b/path/resolver.go index e11c2767d..094bc755e 100644 --- a/path/resolver.go +++ b/path/resolver.go @@ -131,15 +131,19 @@ func ResolveSingle(ctx context.Context, ds dag.DAGService, nd node.Node, names [ // It uses the first path component as a hash (key) of the first node, then // resolves all other components walking the links, with ResolveLinks. func (s *Resolver) ResolvePathComponents(ctx context.Context, fpath Path) ([]node.Node, error) { + evt := log.EventBegin(ctx, "resolvePathComponents", logging.LoggableMap{"fpath": fpath}) + defer evt.Done() + h, parts, err := SplitAbsPath(fpath) if err != nil { + evt.Append(logging.LoggableMap{"error": err.Error()}) return nil, err } - defer log.EventBegin(ctx, "resolvePathComponents", logging.LoggableMap{"parts": parts, "cid": h}).Done() log.Debug("resolve dag get") nd, err := s.DAG.Get(ctx, h) if err != nil { + evt.Append(logging.LoggableMap{"error": err.Error()}) return nil, err } @@ -155,7 +159,8 @@ func (s *Resolver) ResolvePathComponents(ctx context.Context, fpath Path) ([]nod // would retrieve "baz" in ("bar" in ("foo" in nd.Links).Links).Links func (s *Resolver) ResolveLinks(ctx context.Context, ndd node.Node, names []string) ([]node.Node, error) { - defer log.EventBegin(ctx, "resolveLinks", logging.LoggableMap{"names": names}).Done() + evt := log.EventBegin(ctx, "resolveLinks", logging.LoggableMap{"names": names}) + defer evt.Done() result := make([]node.Node, 0, len(names)+1) result = append(result, ndd) nd := ndd // dup arg workaround @@ -168,13 +173,16 @@ func (s *Resolver) ResolveLinks(ctx context.Context, ndd node.Node, names []stri lnk, rest, err := s.ResolveOnce(ctx, s.DAG, nd, names) if err == dag.ErrLinkNotFound { + evt.Append(logging.LoggableMap{"error": err.Error()}) return result, ErrNoLink{Name: names[0], Node: nd.Cid()} } else if err != nil { + evt.Append(logging.LoggableMap{"error": err.Error()}) return result, err } nextnode, err := lnk.GetNode(ctx, s.DAG) if err != nil { + evt.Append(logging.LoggableMap{"error": err.Error()}) return result, err }