.

go/internal/task/task.go

@@ -38,7 +38,7 @@ func Running(ctxp *context.Context, name string) func(*error) {
 	return running(ctxp, name)
 }
 
-// Runningf is Running cousin with formatting support
+// Runningf is Running with formatting support.
 func Runningf(ctxp *context.Context, format string, argv ...interface{}) func(*error) {
 	return running(ctxp, fmt.Sprintf(format, argv...))
 }
@@ -46,17 +46,48 @@ func Runningf(ctxp *context.Context, format string, argv ...interface{}) func(*e
 func running(ctxp *context.Context, name string) func(*error) {
 	ctx := taskctx.Running(*ctxp, name)
 	*ctxp = ctx
-	log.Depth(2).Info(ctx, "[") // TODO log -> trace, don't put ":" before "["
+	traceBegin(3, ctx)
 
 	return func(errp *error) {
-		err := ""
-		if e := *errp; e != nil {
-			err = fmt.Sprintf(" (%s)", e)
-		}
-		log.Depth(1).Info(ctx, "]"+err) // TODO log -> trace, don't put ":" before "]"
+		traceEnd(2, ctx, *errp) // XXX recheck 2
 
 		// NOTE not *ctxp here - as context pointed by ctxp could be
 		// changed when this deferred function is run
 		taskctx.ErrContext(errp, ctx)
 	}
 }
+
+
+/*
+// RunningNoErrCtx is like Running but does not adjust error return with task prefix.
+func RunningNoErrCtx(ctxp *context.Context, name string) func(*error) {
+	// XXX
+}
+
+// RunningfNoErrCtx is RunningNoErrCtx with formatting support.
+func RunningfNoErrCtx(ctxp *context.Context, format string, argv ...interface{}) func(*error) {
+}
+*/
+
+// TraceBegin traces beginning of a task.
+func TraceBegin(ctx context.Context) {
+	traceBegin(2, ctx)
+}
+
+// TraceEnd traces end of a task.
+func TraceEnd(ctx context.Context, err error) {
+	traceEnd(2, ctx, err)
+}
+
+
+func traceBegin(depth int, ctx context.Context) {
+	log.Depth(depth).Info(ctx, "[") // TODO log -> trace, don't put ":" before "["
+}
+
+func traceEnd(depth int, ctx context.Context, err error) {
+	e := ""
+	if err != nil {
+		e = fmt.Sprintf(" (%s)", err)
+	}
+	log.Depth(depth).Info(ctx, "]"+e) // TODO log -> trace, don't put ":" before "]"
+}

go/internal/xcontext/task/task.go

@@ -39,6 +39,7 @@ func (t *Task) Name() string  { return t.name   }
 type taskKey struct{}
 
 // Running creates new task and returns new context with that task set to current.
+// XXX -> New?
 func Running(ctx context.Context, name string) context.Context {
 	return context.WithValue(ctx, taskKey{}, &Task{parent: Current(ctx), name: name})
 }

go/neo/client.go

@@ -29,6 +29,7 @@ import (
 	"strings"
 	"sync"
 
+	"github.com/golang/glog"
 	"github.com/pkg/errors"
 	"lab.nexedi.com/kirr/go123/mem"
 	"lab.nexedi.com/kirr/go123/xcontext"
@@ -36,6 +37,7 @@ import (
 	"lab.nexedi.com/kirr/go123/xsync"
 
 	"lab.nexedi.com/kirr/neo/go/internal/task"
+	taskctx "lab.nexedi.com/kirr/neo/go/internal/xcontext/task"
 	"lab.nexedi.com/kirr/neo/go/internal/xurl"
 	"lab.nexedi.com/kirr/neo/go/internal/xzlib"
 	"lab.nexedi.com/kirr/neo/go/internal/xzodb"
@@ -288,14 +290,17 @@ func (c *Client) Sync(ctx context.Context) (head zodb.Tid, err error) {
 
 // Load implements zodb.IStorageDriver.
 func (c *Client) Load(ctx context.Context, xid zodb.Xid) (buf *mem.Buf, serial zodb.Tid, err error) {
+	ctx = taskctx.Runningf(ctx, "%s: zload %s", c.node.MyInfo.NID, xid) // XXX nid locking
+	if glog.V(2) {
+		task.TraceBegin(ctx)
+		defer func() { task.TraceEnd(ctx, err) }()
+	}
 	defer func() {
 		if err != nil {
 			err = &zodb.OpError{URL: c.URL(), Op: "load", Args: xid, Err: err}
 		}
 	}()
 
-//	defer task.Runningf(&ctx, "%s: zload %s", c.nid, xid)(&err)	// XXX enable
-
 	// Retrieve storages we might need to access.
 	storv := make([]*xneo.PeerNode, 0, 1)
 	err = c.node.WithOperational(ctx, func(mlink *neonet.NodeLink, cs *xneo.ClusterState) error {

go/neo/xneo/nodetab.go

@@ -321,12 +321,13 @@ func (p *PeerNode) ResetLink(ctx context.Context) {
 // XXX p.* reading without lock - ok?
 // XXX node.MyInfo without lock - ok?
 func (p *PeerNode) dial(ctx context.Context) (_ *neonet.NodeLink, err error) {
+	node := p.nodeTab.localNode
+	mynid := node.MyInfo.NID // XXX locking
 	defer task.Runningf(&ctx, "dial %s", p.NID)(&err)
 
-	node := p.nodeTab.localNode
 	reqID := &proto.RequestIdentification{
 		NodeType:	node.MyInfo.Type,
-		NID:		node.MyInfo.NID,
+		NID:		mynid,
 		Address:	node.MyInfo.Addr,
 		ClusterName:	node.ClusterName,
 		IdTime:		node.MyInfo.IdTime,	// XXX ok?