diff --git a/modules/mesh-grants/cmd/mesh-grants/main.go b/modules/mesh-grants/cmd/mesh-grants/main.go index ea6860c0..2e86973f 100644 --- a/modules/mesh-grants/cmd/mesh-grants/main.go +++ b/modules/mesh-grants/cmd/mesh-grants/main.go @@ -28,6 +28,7 @@ import ( "os/signal" "strings" "syscall" + "time" "github.com/nats-io/nats.go" "github.com/nats-io/nats.go/jetstream" @@ -117,7 +118,7 @@ func run(ctx context.Context, getenv func(string) string, logOut io.Writer) erro // followed on the owners' views families, which the hearing below hands them. sayCond := sayVia(ctx, js, account.Module) fv := grants.NewViews(func(tool string) func(context.Context, string) (views.Answer, error) { - return views.AskVia(grants.Unwrapped(conn.Call), tool) + return grants.TimedAsk(tool, views.AskVia(grants.Unwrapped(conn.Call), tool), time.Now, logger.Printf) }, sayCond, f.Wake, logger.Printf) fv.Rest, fv.Watching = bus, bus byState := map[string]*views.Follower{} diff --git a/modules/mesh-grants/grants_test.go b/modules/mesh-grants/grants_test.go index bf3fc9ea..09d41dd1 100644 --- a/modules/mesh-grants/grants_test.go +++ b/modules/mesh-grants/grants_test.go @@ -3905,6 +3905,28 @@ func TestGrants(t *testing.T) { t.Errorf("the kept tool runner was not said: %+v", last) } }) + + // Each first view's page says in the log how long it took (issue 1966: the wants page outgrew the call's bound unseen). + t.Run("a first view's page says how long it took", func(t *testing.T) { + at := time.Date(2026, 11, 8, 22, 0, 0, 0, time.UTC) + now := func() time.Time { at = at.Add(1500 * time.Millisecond); return at } + for _, row := range []struct { + name string + err error + want string + }{ + {"answered", nil, `the first view mesh-delivery-assigner.wants, the page after "", took 1.5s: 2 keys at revision 9, next ""`}, + {"failed", errors.New("context deadline exceeded"), `the first view mesh-delivery-assigner.wants, the page after "", failed after 1.5s: context deadline exceeded`}, + } { + var lines []string + ask := grants.TimedAsk(grants.ReadWants, func(context.Context, string) (views.Answer, error) { + return views.Answer{Revision: 9, Values: map[string]json.RawMessage{"a": nil, "b": nil}}, row.err + }, now, func(f string, a ...any) { lines = append(lines, fmt.Sprintf(f, a...)) }) + if _, err := ask(context.Background(), ""); !errors.Is(err, row.err) || len(lines) != 1 || !strings.Contains(lines[0], row.want) { + t.Errorf("%s: said %q (%v), want %q", row.name, lines, err, row.want) + } + } + }) } // fakeObjects is the part's object bucket of sealed lists. diff --git a/modules/mesh-grants/internal/grants/firstviews.go b/modules/mesh-grants/internal/grants/firstviews.go index b4e5389b..11aace93 100644 --- a/modules/mesh-grants/internal/grants/firstviews.go +++ b/modules/mesh-grants/internal/grants/firstviews.go @@ -479,6 +479,26 @@ func (p *Part) AskFirstViewAgain(caller, state, why string, record func(what, wh "says": "the part's process asks it once more at this ask; grants_first_views shows its answer"}, nil } +// TimedAsk is ask, saying in the log how long each page took and how many keys it brought, or after how long it failed: +// a first view that never answers (issue 1966: the wants page outgrew the call's bound) shows how far from its bound it is. +func TimedAsk(tool string, ask func(context.Context, string) (views.Answer, error), now func() time.Time, + logf func(string, ...any)) func(context.Context, string) (views.Answer, error) { + return func(ctx context.Context, after string) (views.Answer, error) { + start := now() + a, err := ask(ctx, after) + took := now().Sub(start).Round(time.Millisecond) + switch { + case logf == nil: + case err != nil: + logf("[mesh-grants] the first view %s, the page after %q, failed after %s: %v", tool, after, took, err) + default: + logf("[mesh-grants] the first view %s, the page after %q, took %s: %d keys at revision %d, next %q", tool, after, took, + len(a.Values), a.Revision, a.Next) + } + return a, err + } +} + // Unwrapped is a call whose answer is read as the tool's own text where the runtime wraps it as content (unwrap), as // a first view's answer is decoded (views.AskVia). func Unwrapped(call func(key string, body any) (json.RawMessage, error)) func(key string, body any) (json.RawMessage, error) {