Investigate the duplicate calls to v23.Dispatcher.Lookup

[razvanm]

When creating a server using v23.WithNewDispatchingServer and a custom dispatcher I see that the v23.Dispatcher.Lookup is invoked twice for each incoming RPC.

Sample traces obtained using -log_backtrace_at=main.go:59:

I0317 10:07:06.708271   20437 main.go:59] suffix: "a/b/c" ctx: &{parent:0xc42021fae0 logger:0xc420010480 ctxLogger:0x11f3f38 key:2 value:0xc4203d3cc0}
goroutine 204 [running]:
grail.com/vendor/github.com/cosnicolaou/llog.stacks(0xc42001e100, 0x418000, 0x7, 0x3b, 0xc4205b9301)
	/home/razvanm/work/grail/go/src/grail.com/vendor/github.com/cosnicolaou/llog/glog.go:914 +0x96
grail.com/vendor/github.com/cosnicolaou/llog.(*Log).output(0xc42001e140, 0xc400000000, 0xc420090420, 0xf7bb28, 0x7, 0x3b)
	/home/razvanm/work/grail/go/src/grail.com/vendor/github.com/cosnicolaou/llog/glog.go:835 +0x61c
grail.com/vendor/github.com/cosnicolaou/llog.(*Log).PrintfDepth(0xc42001e140, 0x0, 0x1, 0xc1cd6d, 0x13, 0xc4205b9688, 0x2, 0x2)
	/home/razvanm/work/grail/go/src/grail.com/vendor/github.com/cosnicolaou/llog/glog.go:827 +0x14e
grail.com/vendor/github.com/cosnicolaou/llog.(*Log).Printf(0xc42001e140, 0xc400000000, 0xc1cd6d, 0x13, 0xc4205b9688, 0x2, 0x2)
	/home/razvanm/work/grail/go/src/grail.com/vendor/github.com/cosnicolaou/llog/glog.go:803 +0x71
grail.com/vendor/v.io/x/lib/vlog.Infof(0xc1cd6d, 0x13, 0xc4205b9688, 0x2, 0x2)
	/home/razvanm/work/grail/go/src/grail.com/vendor/v.io/x/lib/vlog/funcs.go:21 +0x6a
main.(*dispatcher).Lookup(0xc4202fde90, 0xc42021fb30, 0xc42040e560, 0x5, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/home/razvanm/work/grail/go/src/grail.com/experimental/users/razvanm/profile/profile-server/main.go:59 +0x158
grail.com/vendor/v.io/x/ref/runtime/internal/rpc.(*flowServer).lookup(0xc42009c3c0, 0xc42021fb30, 0xc42040e560, 0x5, 0xc42040e565, 0xb, 0x80d860a50e3119, 0x0, 0xc42021fa90, 0x11ae080, ...)
	/home/razvanm/work/grail/go/src/grail.com/vendor/v.io/x/ref/runtime/internal/rpc/server.go:904 +0x1d8
grail.com/vendor/v.io/x/ref/runtime/internal/rpc.(*flowServer).processRequest(0xc42009c3c0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/home/razvanm/work/grail/go/src/grail.com/vendor/v.io/x/ref/runtime/internal/rpc/server.go:808 +0xbc3
grail.com/vendor/v.io/x/ref/runtime/internal/rpc.(*flowServer).serve(0xc42009c3c0, 0x0, 0x0)
	/home/razvanm/work/grail/go/src/grail.com/vendor/v.io/x/ref/runtime/internal/rpc/server.go:682 +0xb9
grail.com/vendor/v.io/x/ref/runtime/internal/rpc.(*server).acceptLoop.func2(0xc4203e2000, 0xc4200b88f0, 0x11af9a0, 0xc4200a7340)
	/home/razvanm/work/grail/go/src/grail.com/vendor/v.io/x/ref/runtime/internal/rpc/server.go:565 +0x302
created by grail.com/vendor/v.io/x/ref/runtime/internal/rpc.(*server).acceptLoop
	/home/razvanm/work/grail/go/src/grail.com/vendor/v.io/x/ref/runtime/internal/rpc/server.go:579 +0x136
I0317 10:07:06.709000   20437 main.go:59] suffix: "a/b/c" ctx: &{parent:0xc42021fe50 logger:0xc420010480 ctxLogger:0x11f3f38 key:2 value:0xc42036c8e0}
goroutine 215 [running]:
grail.com/vendor/github.com/cosnicolaou/llog.stacks(0xc42001e100, 0x418000, 0x7, 0x3b, 0xc4205b9301)
	/home/razvanm/work/grail/go/src/grail.com/vendor/github.com/cosnicolaou/llog/glog.go:914 +0x96
grail.com/vendor/github.com/cosnicolaou/llog.(*Log).output(0xc42001e140, 0xc400000000, 0xc420090840, 0xf7bb28, 0x7, 0x3b)
	/home/razvanm/work/grail/go/src/grail.com/vendor/github.com/cosnicolaou/llog/glog.go:835 +0x61c
grail.com/vendor/github.com/cosnicolaou/llog.(*Log).PrintfDepth(0xc42001e140, 0x0, 0x1, 0xc1cd6d, 0x13, 0xc4205b9688, 0x2, 0x2)
	/home/razvanm/work/grail/go/src/grail.com/vendor/github.com/cosnicolaou/llog/glog.go:827 +0x14e
grail.com/vendor/github.com/cosnicolaou/llog.(*Log).Printf(0xc42001e140, 0xc400000000, 0xc1cd6d, 0x13, 0xc4205b9688, 0x2, 0x2)
	/home/razvanm/work/grail/go/src/grail.com/vendor/github.com/cosnicolaou/llog/glog.go:803 +0x71
grail.com/vendor/v.io/x/lib/vlog.Infof(0xc1cd6d, 0x13, 0xc4205b9688, 0x2, 0x2)
	/home/razvanm/work/grail/go/src/grail.com/vendor/v.io/x/lib/vlog/funcs.go:21 +0x6a
main.(*dispatcher).Lookup(0xc4202fde90, 0xc42021fea0, 0xc42040e940, 0x5, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/home/razvanm/work/grail/go/src/grail.com/experimental/users/razvanm/profile/profile-server/main.go:59 +0x158
grail.com/vendor/v.io/x/ref/runtime/internal/rpc.(*flowServer).lookup(0xc4200f45a0, 0xc42021fea0, 0xc42040e940, 0x5, 0xc42040e945, 0x3, 0x80d860a50e3119, 0x0, 0xc42021fe00, 0x11ae080, ...)
	/home/razvanm/work/grail/go/src/grail.com/vendor/v.io/x/ref/runtime/internal/rpc/server.go:904 +0x1d8
grail.com/vendor/v.io/x/ref/runtime/internal/rpc.(*flowServer).processRequest(0xc4200f45a0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
	/home/razvanm/work/grail/go/src/grail.com/vendor/v.io/x/ref/runtime/internal/rpc/server.go:808 +0xbc3
grail.com/vendor/v.io/x/ref/runtime/internal/rpc.(*flowServer).serve(0xc4200f45a0, 0x0, 0x0)
	/home/razvanm/work/grail/go/src/grail.com/vendor/v.io/x/ref/runtime/internal/rpc/server.go:682 +0xb9
grail.com/vendor/v.io/x/ref/runtime/internal/rpc.(*server).acceptLoop.func2(0xc4203e2000, 0xc4200b88f0, 0x11af9a0, 0xc4201ba000)
	/home/razvanm/work/grail/go/src/grail.com/vendor/v.io/x/ref/runtime/internal/rpc/server.go:565 +0x302
created by grail.com/vendor/v.io/x/ref/runtime/internal/rpc.(*server).acceptLoop
	/home/razvanm/work/grail/go/src/grail.com/vendor/v.io/x/ref/runtime/internal/rpc/server.go:579 +0x136
I0317 10:07:06.709092   20437 service.go:16] Get: ctx: &{parent:0xc42021fe50 logger:0xc420010480 ctxLogger:0x11f3f38 key:2 value:0xc42036c8e0} call: &{server:0xc4200b88f0 disp:0xc4202fde90 flow:0xc420190d20 dec:0xc4201f2d20 enc:0xc420208680 grantedBlessings:{chains:[] publicKey:<nil> digests:[] uniqueID:[]} method:Get suffix:a/b/c tags:[0xc420197200] discharges:map[] starttime:{sec:63625367226 nsec:708976262 loc:0x11d7360} endStreamArgs:false removeStat:0xa1bdd0}

From main.go:

    58	func (d *dispatcher) Lookup(ctx *context.T, suffix string) (interface{}, security.Authorizer, error) {
    59		vlog.Infof("suffix: %q ctx: %+v", suffix, ctx)