From f511c7bdefd58db25e06d53dfdb3a39499a684e0 Mon Sep 17 00:00:00 2001 From: Valdemar Pereira Date: Sun, 2 Aug 2026 20:29:00 +0100 Subject: [PATCH 01/20] feat(logs): add source-agnostic log types and filtering --- pkg/logs/filter.go | 151 ++++++++++++++++++++++++++++++++++++++++ pkg/logs/filter_test.go | 62 +++++++++++++++++ pkg/logs/source.go | 69 ++++++++++++++++++ 3 files changed, 282 insertions(+) create mode 100644 pkg/logs/filter.go create mode 100644 pkg/logs/filter_test.go create mode 100644 pkg/logs/source.go diff --git a/pkg/logs/filter.go b/pkg/logs/filter.go new file mode 100644 index 0000000..92e63bc --- /dev/null +++ b/pkg/logs/filter.go @@ -0,0 +1,151 @@ +package logs + +import ( + "fmt" + "regexp" + "strings" +) + +// Level is the severity ladder used for threshold filtering. +type Level int + +const ( + LevelNone Level = 0 // no threshold set + LevelTrace Level = 1 + LevelDebug Level = 2 + LevelInfo Level = 3 + LevelWarn Level = 4 + LevelError Level = 5 + LevelFatal Level = 6 +) + +var levelNames = map[string]Level{ + "trace": LevelTrace, + "debug": LevelDebug, + "info": LevelInfo, + "warn": LevelWarn, + "error": LevelError, + "fatal": LevelFatal, +} + +var levelOrder = []string{"trace", "debug", "info", "warn", "error", "fatal"} + +// ParseLevel maps a level name to a Level. ok is false for unknown names. +func ParseLevel(name string) (Level, bool) { + l, ok := levelNames[strings.ToLower(strings.TrimSpace(name))] + return l, ok +} + +// String returns the lower-case level name, or "" for LevelNone. +func (l Level) String() string { + for name, v := range levelNames { + if v == l { + return name + } + } + return "" +} + +// Filter decides which entries are shown. The zero value matches everything. +type Filter struct { + MinLevel Level + Include *regexp.Regexp + Exclude *regexp.Regexp + SourceType string + // Replicas is keyed by replica short id (r1, r2, ...). An empty map means + // all replicas are visible. + Replicas map[string]bool + + includeSrc string + excludeSrc string +} + +// SetInclude compiles and installs the include pattern; "" clears it. +func (f *Filter) SetInclude(pattern string) error { + if pattern == "" { + f.Include, f.includeSrc = nil, "" + return nil + } + re, err := regexp.Compile(pattern) + if err != nil { + return fmt.Errorf("invalid include pattern %q: %w", pattern, err) + } + f.Include, f.includeSrc = re, pattern + return nil +} + +// SetExclude compiles and installs the exclude pattern; "" clears it. +func (f *Filter) SetExclude(pattern string) error { + if pattern == "" { + f.Exclude, f.excludeSrc = nil, "" + return nil + } + re, err := regexp.Compile(pattern) + if err != nil { + return fmt.Errorf("invalid exclude pattern %q: %w", pattern, err) + } + f.Exclude, f.excludeSrc = re, pattern + return nil +} + +// Match reports whether the entry passes every active filter. +func (f *Filter) Match(e Entry) bool { + if f.MinLevel != LevelNone { + lvl, ok := ParseLevel(e.Level) + if !ok || lvl < f.MinLevel { + return false + } + } + if f.SourceType != "" && f.SourceType != e.SourceType { + return false + } + if f.Include != nil && !f.Include.MatchString(e.Message) { + return false + } + if f.Exclude != nil && f.Exclude.MatchString(e.Message) { + return false + } + if len(f.Replicas) > 0 && e.ReplicaID != "" && !f.Replicas[e.ReplicaID] { + return false + } + return true +} + +// Summary renders the active filters for the status footer. +func (f *Filter) Summary() string { + var parts []string + if f.MinLevel != LevelNone { + parts = append(parts, "level>="+f.MinLevel.String()) + } + if f.SourceType != "" { + parts = append(parts, "source="+f.SourceType) + } + if f.includeSrc != "" { + parts = append(parts, "/"+f.includeSrc+"/") + } + if f.excludeSrc != "" { + parts = append(parts, "!/"+f.excludeSrc+"/") + } + if n := len(f.Replicas); n > 0 { + parts = append(parts, fmt.Sprintf("%d replica(s)", n)) + } + if len(parts) == 0 { + return "no filters" + } + return strings.Join(parts, " · ") +} + +// NextLevel cycles the threshold: none -> trace -> ... -> fatal -> none. +// Used by the Phase 2 interactive key handler. +func NextLevel(l Level) Level { + if l == LevelNone { + return LevelTrace + } + if l >= LevelFatal { + return LevelNone + } + return l + 1 +} + +// LevelNames returns the ladder in order, for help text. +func LevelNames() []string { return levelOrder } diff --git a/pkg/logs/filter_test.go b/pkg/logs/filter_test.go new file mode 100644 index 0000000..9a78a84 --- /dev/null +++ b/pkg/logs/filter_test.go @@ -0,0 +1,62 @@ +package logs + +import ( + "testing" + "time" + + "github.com/stretchr/testify/require" +) + +func entry(level, msg, host, sourceType string) Entry { + return Entry{Timestamp: time.Unix(0, 0), Level: level, Message: msg, Hostname: host, SourceType: sourceType} +} + +func TestFilterMatch_Level(t *testing.T) { + var f Filter + require.True(t, f.Match(entry("debug", "m", "", "")), "zero filter matches everything") + + lvl, ok := ParseLevel("warn") + require.True(t, ok) + f.MinLevel = lvl + + require.False(t, f.Match(entry("info", "m", "", ""))) + require.True(t, f.Match(entry("warn", "m", "", ""))) + require.True(t, f.Match(entry("error", "m", "", ""))) + // unknown levels are dropped once a threshold is set + require.False(t, f.Match(entry("bogus", "m", "", ""))) +} + +func TestFilterMatch_Regex(t *testing.T) { + var f Filter + require.NoError(t, f.SetInclude("pay.*502")) + require.True(t, f.Match(entry("info", "payment gateway returned 502", "", ""))) + require.False(t, f.Match(entry("info", "all good", "", ""))) + + require.NoError(t, f.SetExclude("(?i)HEALTH")) + require.False(t, f.Match(entry("info", "payment 502 on /health", "", ""))) + + require.Error(t, f.SetInclude("("), "invalid regex must error") +} + +func TestFilterMatch_SourceTypeAndReplica(t *testing.T) { + f := Filter{SourceType: "application"} + require.True(t, f.Match(entry("info", "m", "", "application"))) + require.False(t, f.Match(entry("info", "m", "", "provider"))) + + f = Filter{Replicas: map[string]bool{"r1": true}} + require.True(t, f.Match(Entry{Level: "info", ReplicaID: "r1"})) + require.False(t, f.Match(Entry{Level: "info", ReplicaID: "r2"})) + // entries with no replica id are always visible (source cannot supply it) + require.True(t, f.Match(Entry{Level: "info"})) +} + +func TestFilterSummary(t *testing.T) { + var f Filter + require.Equal(t, "no filters", f.Summary()) + + lvl, _ := ParseLevel("error") + f.MinLevel = lvl + require.NoError(t, f.SetInclude("boom")) + require.Contains(t, f.Summary(), "level>=error") + require.Contains(t, f.Summary(), "/boom/") +} diff --git a/pkg/logs/source.go b/pkg/logs/source.go new file mode 100644 index 0000000..4fa3d27 --- /dev/null +++ b/pkg/logs/source.go @@ -0,0 +1,69 @@ +// Package logs holds source-agnostic log retrieval, filtering and rendering for +// the CLI's log commands. Sources (Hasura GraphQL today, an SSE log-stream +// service later) are adapted to a single Entry/Source shape so the command loop +// does not care where lines come from. +package logs + +import ( + "context" + "errors" + "time" +) + +// ErrPagingUnsupported is returned by a Source when a caller asks for a page +// older than a cursor but the underlying backend cannot express it. +var ErrPagingUnsupported = errors.New("this log source does not support paging older than a cursor") + +// Entry is one normalized log line. Hostname, LogSource, SourceID and ReplicaID +// are empty when the source cannot supply them; see Caps.Replicas. +type Entry struct { + ID string `json:"id,omitempty"` + Timestamp time.Time `json:"timestamp"` + Level string `json:"log_level"` + Message string `json:"message"` + SourceType string `json:"source_type,omitempty"` + SourceID string `json:"source_id,omitempty"` + Hostname string `json:"hostname,omitempty"` + LogSource string `json:"log_source,omitempty"` + // ReplicaID is the short id (r1, r2, ...) assigned locally by a Registry. + ReplicaID string `json:"replica,omitempty"` +} + +// Query describes which entries to retrieve. +type Query struct { + InstanceID string + From, To time.Time + Limit int + // Cursor is opaque and source-defined; empty means "newest". + Cursor string + SourceType string + // Substring is an optional server-side pre-filter where the source supports it. + Substring string +} + +// Page is one page of entries, newest-first. +type Page struct { + Entries []Entry + // Cursor is passed back as Query.Cursor to fetch the next older page. + Cursor string + HasMore bool +} + +// Caps describes what a Source can do, so callers can enable or hide features +// instead of guessing. +type Caps struct { + // Replicas is true when Hostname/LogSource are populated. + Replicas bool + // Push is true for server-push transports, false for client polling. + Push bool +} + +// Source retrieves log entries. +type Source interface { + Name() string + Caps() Caps + // History returns one page of stored entries, newest-first. + History(ctx context.Context, q Query) (Page, error) + // Follow delivers new entries to out until ctx is cancelled. + Follow(ctx context.Context, q Query, out chan<- Entry) error +} From 4ea112b92a022fbeab6caaa218de50fe5ab8fd34 Mon Sep 17 00:00:00 2001 From: Valdemar Pereira Date: Sun, 2 Aug 2026 20:38:20 +0100 Subject: [PATCH 02/20] feat(logs): add bounded ring buffer for retained entries --- pkg/logs/buffer.go | 55 +++++++++++++++++++++++++++++++++++++++++ pkg/logs/buffer_test.go | 36 +++++++++++++++++++++++++++ 2 files changed, 91 insertions(+) create mode 100644 pkg/logs/buffer.go create mode 100644 pkg/logs/buffer_test.go diff --git a/pkg/logs/buffer.go b/pkg/logs/buffer.go new file mode 100644 index 0000000..2e3671b --- /dev/null +++ b/pkg/logs/buffer.go @@ -0,0 +1,55 @@ +package logs + +import "sync" + +// DefaultBufferSize is the number of entries retained in memory when the user +// does not override --buffer. +const DefaultBufferSize = 5000 + +// Buffer is a bounded, drop-oldest ring buffer of entries. It is safe for +// concurrent use: a source goroutine appends while the render loop snapshots. +type Buffer struct { + mu sync.Mutex + entries []Entry + capacity int +} + +// NewBuffer returns a buffer holding at most capacity entries. A non-positive +// capacity falls back to DefaultBufferSize. +func NewBuffer(capacity int) *Buffer { + if capacity <= 0 { + capacity = DefaultBufferSize + } + return &Buffer{entries: make([]Entry, 0, capacity), capacity: capacity} +} + +// Add appends an entry, evicting the oldest when full. +func (b *Buffer) Add(e Entry) { + b.mu.Lock() + defer b.mu.Unlock() + if len(b.entries) == b.capacity { + copy(b.entries, b.entries[1:]) + b.entries[len(b.entries)-1] = e + return + } + b.entries = append(b.entries, e) +} + +// Snapshot returns a copy of the retained entries, oldest-first. +func (b *Buffer) Snapshot() []Entry { + b.mu.Lock() + defer b.mu.Unlock() + out := make([]Entry, len(b.entries)) + copy(out, b.entries) + return out +} + +// Len returns the number of retained entries. +func (b *Buffer) Len() int { + b.mu.Lock() + defer b.mu.Unlock() + return len(b.entries) +} + +// Cap returns the configured capacity. +func (b *Buffer) Cap() int { return b.capacity } diff --git a/pkg/logs/buffer_test.go b/pkg/logs/buffer_test.go new file mode 100644 index 0000000..6d70144 --- /dev/null +++ b/pkg/logs/buffer_test.go @@ -0,0 +1,36 @@ +package logs + +import ( + "testing" + + "github.com/stretchr/testify/require" +) + +func TestBuffer_DropsOldest(t *testing.T) { + b := NewBuffer(3) + require.Equal(t, 3, b.Cap()) + + for _, m := range []string{"a", "b", "c", "d", "e"} { + b.Add(Entry{Message: m}) + } + + require.Equal(t, 3, b.Len()) + got := []string{} + for _, e := range b.Snapshot() { + got = append(got, e.Message) + } + require.Equal(t, []string{"c", "d", "e"}, got, "keeps newest, oldest-first order") +} + +func TestBuffer_SnapshotIsACopy(t *testing.T) { + b := NewBuffer(2) + b.Add(Entry{Message: "a"}) + snap := b.Snapshot() + b.Add(Entry{Message: "b"}) + require.Len(t, snap, 1, "snapshot must not change when the buffer does") +} + +func TestBuffer_NonPositiveCapacityFallsBackToDefault(t *testing.T) { + require.Equal(t, DefaultBufferSize, NewBuffer(0).Cap()) + require.Equal(t, DefaultBufferSize, NewBuffer(-5).Cap()) +} From f5048485bc82f9022dded342340a4aa5507a1a2b Mon Sep 17 00:00:00 2001 From: Valdemar Pereira Date: Sun, 2 Aug 2026 20:46:31 +0100 Subject: [PATCH 03/20] test(logs): enforce buffer copy and concurrency guarantees --- pkg/logs/buffer.go | 11 ++++++--- pkg/logs/buffer_test.go | 53 +++++++++++++++++++++++++++++++++++++++-- 2 files changed, 59 insertions(+), 5 deletions(-) diff --git a/pkg/logs/buffer.go b/pkg/logs/buffer.go index 2e3671b..35f1430 100644 --- a/pkg/logs/buffer.go +++ b/pkg/logs/buffer.go @@ -6,8 +6,11 @@ import "sync" // does not override --buffer. const DefaultBufferSize = 5000 -// Buffer is a bounded, drop-oldest ring buffer of entries. It is safe for -// concurrent use: a source goroutine appends while the render loop snapshots. +// Buffer retains at most a fixed number of entries in a bounded slice. Once +// full, adding an entry drops the oldest by shifting the remaining entries down +// one position, so Add is O(n) in the capacity once the buffer is saturated. +// It is safe for concurrent use: a source goroutine appends while the render +// loop snapshots. type Buffer struct { mu sync.Mutex entries []Entry @@ -51,5 +54,7 @@ func (b *Buffer) Len() int { return len(b.entries) } -// Cap returns the configured capacity. +// Cap returns the configured capacity. It is deliberately lock-free because +// capacity is immutable after construction; if the buffer ever gains a resize +// operation, this must start taking b.mu like Len does. func (b *Buffer) Cap() int { return b.capacity } diff --git a/pkg/logs/buffer_test.go b/pkg/logs/buffer_test.go index 6d70144..d80228c 100644 --- a/pkg/logs/buffer_test.go +++ b/pkg/logs/buffer_test.go @@ -1,6 +1,7 @@ package logs import ( + "sync" "testing" "github.com/stretchr/testify/require" @@ -23,11 +24,59 @@ func TestBuffer_DropsOldest(t *testing.T) { } func TestBuffer_SnapshotIsACopy(t *testing.T) { + // Fill to capacity so the next Add takes the shift/evict path, which + // mutates the backing array in place. A snapshot that shared that array + // would observe the mutation. b := NewBuffer(2) b.Add(Entry{Message: "a"}) - snap := b.Snapshot() b.Add(Entry{Message: "b"}) - require.Len(t, snap, 1, "snapshot must not change when the buffer does") + + snap := b.Snapshot() + require.Len(t, snap, 2) + + b.Add(Entry{Message: "c"}) + + require.Len(t, snap, 2, "snapshot length must not change when the buffer does") + require.Equal(t, "a", snap[0].Message, "snapshot elements must not be mutated by a later Add") + require.Equal(t, "b", snap[1].Message, "snapshot elements must not be mutated by a later Add") + + // Sanity: the buffer itself did evict, so the assertions above are not + // passing simply because nothing happened. + require.Equal(t, []string{"b", "c"}, messages(b.Snapshot())) +} + +func TestBuffer_ConcurrentAddAndSnapshot(t *testing.T) { + const iterations = 500 + + b := NewBuffer(16) + + var wg sync.WaitGroup + wg.Add(1) + go func() { + defer wg.Done() + for i := 0; i < iterations; i++ { + b.Add(Entry{Message: "entry"}) + } + }() + + for i := 0; i < iterations; i++ { + snap := b.Snapshot() + require.LessOrEqual(t, len(snap), b.Cap()) + require.LessOrEqual(t, b.Len(), b.Cap()) + } + + wg.Wait() + + require.Equal(t, b.Cap(), b.Len()) + require.LessOrEqual(t, b.Len(), b.Cap()) +} + +func messages(entries []Entry) []string { + out := make([]string, 0, len(entries)) + for _, e := range entries { + out = append(out, e.Message) + } + return out } func TestBuffer_NonPositiveCapacityFallsBackToDefault(t *testing.T) { From 682b8d25951497dbfe43cc0c3b2aeda801ad40fc Mon Sep 17 00:00:00 2001 From: Valdemar Pereira Date: Sun, 2 Aug 2026 20:54:38 +0100 Subject: [PATCH 04/20] feat(logs): add dynamic replica registry with stable short ids --- pkg/logs/registry.go | 91 +++++++++++++++++++++++++++++++++++++++ pkg/logs/registry_test.go | 90 ++++++++++++++++++++++++++++++++++++++ 2 files changed, 181 insertions(+) create mode 100644 pkg/logs/registry.go create mode 100644 pkg/logs/registry_test.go diff --git a/pkg/logs/registry.go b/pkg/logs/registry.go new file mode 100644 index 0000000..7b58b73 --- /dev/null +++ b/pkg/logs/registry.go @@ -0,0 +1,91 @@ +package logs + +import ( + "fmt" + "strings" + "sync" +) + +// Replica is a log-producing instance replica discovered from the stream. +type Replica struct { + ShortID string // r1, r2, ... + Hostname string + // ColorIndex is a stable index the renderer maps to a terminal colour. + ColorIndex int + Count int +} + +// Registry assigns stable short ids to replica hostnames as they are first seen, +// so a user can select or mute them by a short name. +type Registry struct { + mu sync.Mutex + byID map[string]*Replica + byHost map[string]*Replica + order []*Replica +} + +// NewRegistry returns an empty registry. +func NewRegistry() *Registry { + return &Registry{byID: map[string]*Replica{}, byHost: map[string]*Replica{}} +} + +// Ensure registers the hostname if new and returns its Replica. An empty +// hostname is never registered and yields the zero Replica. +func (r *Registry) Ensure(hostname string) Replica { + if hostname == "" { + return Replica{} + } + r.mu.Lock() + defer r.mu.Unlock() + if rep, ok := r.byHost[hostname]; ok { + rep.Count++ + return *rep + } + rep := &Replica{ + ShortID: fmt.Sprintf("r%d", len(r.order)+1), + Hostname: hostname, + ColorIndex: len(r.order), + Count: 1, + } + r.byHost[hostname] = rep + r.byID[rep.ShortID] = rep + r.order = append(r.order, rep) + return *rep +} + +// List returns all known replicas in first-seen order. +func (r *Registry) List() []Replica { + r.mu.Lock() + defer r.mu.Unlock() + out := make([]Replica, 0, len(r.order)) + for _, rep := range r.order { + out = append(out, *rep) + } + return out +} + +// Resolve looks a replica up by exact short id, exact hostname, or hostname +// substring (in that order). +func (r *Registry) Resolve(token string) (Replica, bool) { + r.mu.Lock() + defer r.mu.Unlock() + if rep, ok := r.byID[token]; ok { + return *rep, true + } + if rep, ok := r.byHost[token]; ok { + return *rep, true + } + for _, rep := range r.order { + if token != "" && strings.Contains(rep.Hostname, token) { + return *rep, true + } + } + return Replica{}, false +} + +// Len returns the number of known replicas. +func (r *Registry) Len() int { + r.mu.Lock() + defer r.mu.Unlock() + return len(r.order) +} diff --git a/pkg/logs/registry_test.go b/pkg/logs/registry_test.go new file mode 100644 index 0000000..217e727 --- /dev/null +++ b/pkg/logs/registry_test.go @@ -0,0 +1,90 @@ +package logs + +import ( + "fmt" + "sync" + "testing" + + "github.com/stretchr/testify/require" +) + +func TestRegistry_AssignsStableShortIDs(t *testing.T) { + r := NewRegistry() + + a := r.Ensure("vcr-app-7d4f9c8b6-x2k9p") + b := r.Ensure("vcr-app-7d4f9c8b6-qq111") + again := r.Ensure("vcr-app-7d4f9c8b6-x2k9p") + + require.Equal(t, "r1", a.ShortID) + require.Equal(t, "r2", b.ShortID) + require.Equal(t, "r1", again.ShortID, "same hostname keeps its id") + require.Equal(t, 2, r.Len()) + require.NotEqual(t, a.ColorIndex, b.ColorIndex) +} + +func TestRegistry_EmptyHostnameIsNotRegistered(t *testing.T) { + r := NewRegistry() + got := r.Ensure("") + require.Equal(t, "", got.ShortID) + require.Equal(t, 0, r.Len()) +} + +func TestRegistry_ListIsFirstSeenOrder(t *testing.T) { + r := NewRegistry() + r.Ensure("host-b") + r.Ensure("host-a") + list := r.List() + require.Len(t, list, 2) + require.Equal(t, "host-b", list[0].Hostname) + require.Equal(t, "host-a", list[1].Hostname) +} + +func TestRegistry_ResolveByShortIDOrHostnameSubstring(t *testing.T) { + r := NewRegistry() + r.Ensure("vcr-app-abc-12345") + + got, ok := r.Resolve("r1") + require.True(t, ok) + require.Equal(t, "vcr-app-abc-12345", got.Hostname) + + got, ok = r.Resolve("12345") + require.True(t, ok) + require.Equal(t, "r1", got.ShortID) + + _, ok = r.Resolve("nope") + require.False(t, ok) +} + +func TestRegistry_ConcurrentEnsureAndList(t *testing.T) { + r := NewRegistry() + + const writers = 8 + const perWriter = 50 + + var wg sync.WaitGroup + wg.Add(writers * 2) + for w := 0; w < writers; w++ { + go func(w int) { + defer wg.Done() + for i := 0; i < perWriter; i++ { + r.Ensure(fmt.Sprintf("host-%d", i%4)) + } + }(w) + go func() { + defer wg.Done() + for i := 0; i < perWriter; i++ { + _ = r.List() + _ = r.Len() + _, _ = r.Resolve("r1") + } + }() + } + wg.Wait() + + require.Equal(t, 4, r.Len(), "only distinct hostnames are registered") + total := 0 + for _, rep := range r.List() { + total += rep.Count + } + require.Equal(t, writers*perWriter, total, "every Ensure is counted exactly once") +} From 1c43a90eaefb4ad7a15737384d49e6d4e5e4628b Mon Sep 17 00:00:00 2001 From: Valdemar Pereira Date: Sun, 2 Aug 2026 21:01:40 +0100 Subject: [PATCH 05/20] test(logs): pin registry resolve precedence and document replica fields --- pkg/logs/registry.go | 10 +++++++--- pkg/logs/registry_test.go | 36 ++++++++++++++++++++++++++++++++++-- 2 files changed, 41 insertions(+), 5 deletions(-) diff --git a/pkg/logs/registry.go b/pkg/logs/registry.go index 7b58b73..88c2baa 100644 --- a/pkg/logs/registry.go +++ b/pkg/logs/registry.go @@ -10,9 +10,12 @@ import ( type Replica struct { ShortID string // r1, r2, ... Hostname string - // ColorIndex is a stable index the renderer maps to a terminal colour. + // ColorIndex is a stable index the renderer maps to a terminal colour. It is + // unbounded (it is len(order) at the time the replica was first seen), so a + // renderer must take it modulo its palette size. ColorIndex int - Count int + // Count is the number of log entries seen from this replica. + Count int } // Registry assigns stable short ids to replica hostnames as they are first seen, @@ -65,7 +68,8 @@ func (r *Registry) List() []Replica { } // Resolve looks a replica up by exact short id, exact hostname, or hostname -// substring (in that order). +// substring (in that order). The substring tier returns the FIRST first-seen +// match, not the most specific one. func (r *Registry) Resolve(token string) (Replica, bool) { r.mu.Lock() defer r.mu.Unlock() diff --git a/pkg/logs/registry_test.go b/pkg/logs/registry_test.go index 217e727..e9f09e0 100644 --- a/pkg/logs/registry_test.go +++ b/pkg/logs/registry_test.go @@ -55,6 +55,27 @@ func TestRegistry_ResolveByShortIDOrHostnameSubstring(t *testing.T) { require.False(t, ok) } +func TestRegistry_ResolveExactHostnameBeatsEarlierSubstringMatch(t *testing.T) { + r := NewRegistry() + // xabcx is registered FIRST and contains "abc" as a substring, so a + // substring-first Resolve would return it. The exact-hostname tier must win. + r.Ensure("xabcx") + r.Ensure("abc") + + got, ok := r.Resolve("abc") + require.True(t, ok) + require.Equal(t, "abc", got.Hostname, "exact hostname match must beat an earlier-registered substring match") + require.Equal(t, "r2", got.ShortID) +} + +func TestRegistry_ResolveEmptyTokenIsNotFound(t *testing.T) { + r := NewRegistry() + r.Ensure("vcr-app-abc-12345") + + _, ok := r.Resolve("") + require.False(t, ok, "an empty token must never resolve") +} + func TestRegistry_ConcurrentEnsureAndList(t *testing.T) { r := NewRegistry() @@ -64,12 +85,12 @@ func TestRegistry_ConcurrentEnsureAndList(t *testing.T) { var wg sync.WaitGroup wg.Add(writers * 2) for w := 0; w < writers; w++ { - go func(w int) { + go func() { defer wg.Done() for i := 0; i < perWriter; i++ { r.Ensure(fmt.Sprintf("host-%d", i%4)) } - }(w) + }() go func() { defer wg.Done() for i := 0; i < perWriter; i++ { @@ -87,4 +108,15 @@ func TestRegistry_ConcurrentEnsureAndList(t *testing.T) { total += rep.Count } require.Equal(t, writers*perWriter, total, "every Ensure is counted exactly once") + + // A racy len(r.order) read while assigning ShortID would hand the same short + // id to two replicas; assert every id is distinct and accounted for. + list := r.List() + seen := map[string]bool{} + for _, rep := range list { + require.False(t, seen[rep.ShortID], "duplicate ShortID %q assigned", rep.ShortID) + seen[rep.ShortID] = true + } + require.Len(t, seen, r.Len(), "one unique ShortID per registered replica") + require.Len(t, list, r.Len()) } From 52838b9e88e31ebf9ed45075ed4e386a96da8461 Mon Sep 17 00:00:00 2001 From: Valdemar Pereira Date: Sun, 2 Aug 2026 21:09:48 +0100 Subject: [PATCH 06/20] feat(logs): add entry renderer with replica column and JSON mode --- pkg/logs/render.go | 102 ++++++++++++++++++++++++++++++++++++++++ pkg/logs/render_test.go | 56 ++++++++++++++++++++++ 2 files changed, 158 insertions(+) create mode 100644 pkg/logs/render.go create mode 100644 pkg/logs/render_test.go diff --git a/pkg/logs/render.go b/pkg/logs/render.go new file mode 100644 index 0000000..dd7d715 --- /dev/null +++ b/pkg/logs/render.go @@ -0,0 +1,102 @@ +package logs + +import ( + "encoding/json" + "fmt" + "time" + + "github.com/cli/cli/v2/pkg/iostreams" +) + +// timeLayout is the wall-clock format used for each line. +const timeLayout = "15:04:05.000" + +// RenderOptions controls line formatting. +type RenderOptions struct { + // ShowReplica adds the replica short-id column. Callers set this from + // Source.Caps().Replicas. + ShowReplica bool + // JSON emits one JSON object per line instead of the human format. + JSON bool + // UTC prints timestamps in UTC instead of local time. + UTC bool +} + +// Renderer formats entries for the terminal. +type Renderer struct { + cs *iostreams.ColorScheme + opts RenderOptions +} + +// NewRenderer returns a Renderer using the given colour scheme. +func NewRenderer(cs *iostreams.ColorScheme, opts RenderOptions) *Renderer { + return &Renderer{cs: cs, opts: opts} +} + +// Line renders one entry in the human format, without a trailing newline. +func (r *Renderer) Line(e Entry) string { + ts := e.Timestamp.In(time.Local) + if r.opts.UTC { + ts = e.Timestamp.UTC() + } + out := ts.Format(timeLayout) + " " + if r.opts.ShowReplica { + out += r.colorReplica(e.ReplicaID) + " " + } + out += r.colorLevel(e.Level) + " " + e.Message + return out +} + +// JSONLine renders one entry as a single-line JSON object. +func (r *Renderer) JSONLine(e Entry) (string, error) { + b, err := json.Marshal(e) + if err != nil { + return "", fmt.Errorf("failed to encode log entry: %w", err) + } + return string(b), nil +} + +// colorLevel pads the level to a fixed width and colours it by severity. +func (r *Renderer) colorLevel(level string) string { + padded := fmt.Sprintf("%-5s", level) + switch level { + case "error", "fatal": + return r.cs.Red(padded) + case "warn": + return r.cs.Yellow(padded) + case "debug", "trace": + return r.cs.Gray(padded) + default: + return padded + } +} + +// colorReplica colours the replica short id so lines from one replica are easy +// to follow. The colour is derived from the id's trailing digits so it is stable +// without the renderer holding registry state. +func (r *Renderer) colorReplica(shortID string) string { + if shortID == "" { + return " " + } + switch replicaColorIndex(shortID) % 4 { + case 0: + return r.cs.Cyan(shortID) + case 1: + return r.cs.Green(shortID) + case 2: + return r.cs.Magenta(shortID) + default: + return r.cs.Blue(shortID) + } +} + +// replicaColorIndex extracts the numeric part of a short id (r3 -> 3). +func replicaColorIndex(shortID string) int { + n := 0 + for _, c := range shortID { + if c >= '0' && c <= '9' { + n = n*10 + int(c-'0') + } + } + return n +} diff --git a/pkg/logs/render_test.go b/pkg/logs/render_test.go new file mode 100644 index 0000000..396e66e --- /dev/null +++ b/pkg/logs/render_test.go @@ -0,0 +1,56 @@ +package logs + +import ( + "testing" + "time" + + "github.com/cli/cli/v2/pkg/iostreams" + "github.com/stretchr/testify/require" +) + +func testRenderer(t *testing.T, opts RenderOptions) *Renderer { + t.Helper() + ios, _, _, _ := iostreams.Test() // colour disabled in tests + return NewRenderer(ios.ColorScheme(), opts) +} + +func TestRenderer_LineWithoutReplicaColumn(t *testing.T) { + r := testRenderer(t, RenderOptions{UTC: true}) + e := Entry{ + Timestamp: time.Date(2026, 8, 2, 14, 23, 1, 442000000, time.UTC), + Level: "info", + Message: "GET /v1/health 200 3ms", + ReplicaID: "r2", + } + line := r.Line(e) + require.Equal(t, "14:23:01.442 info GET /v1/health 200 3ms", line) + require.NotContains(t, line, "r2", "replica column hidden when ShowReplica is false") +} + +func TestRenderer_LineWithReplicaColumn(t *testing.T) { + r := testRenderer(t, RenderOptions{ShowReplica: true, UTC: true}) + e := Entry{ + Timestamp: time.Date(2026, 8, 2, 14, 23, 1, 610000000, time.UTC), + Level: "error", + Message: "payment gateway returned 502", + ReplicaID: "r1", + } + require.Equal(t, "14:23:01.610 r1 error payment gateway returned 502", r.Line(e)) +} + +func TestRenderer_JSONLine(t *testing.T) { + r := testRenderer(t, RenderOptions{JSON: true, UTC: true}) + e := Entry{ + Timestamp: time.Date(2026, 8, 2, 14, 23, 1, 0, time.UTC), + Level: "warn", + Message: "slow", + Hostname: "host-1", + ReplicaID: "r1", + } + got, err := r.JSONLine(e) + require.NoError(t, err) + require.Contains(t, got, `"log_level":"warn"`) + require.Contains(t, got, `"message":"slow"`) + require.Contains(t, got, `"hostname":"host-1"`) + require.Contains(t, got, `"replica":"r1"`) +} From 40539cf80271e76a5ba42901623730432c7c9712 Mon Sep 17 00:00:00 2001 From: Valdemar Pereira Date: Sun, 2 Aug 2026 21:17:34 +0100 Subject: [PATCH 07/20] fix(logs): honour UTC in JSON output and match levels case-insensitively JSONLine ignored RenderOptions, so the UTC flag only affected human lines. It now normalizes the timestamp on a local copy of the entry the same way Line does, leaving the caller's entry untouched. colorLevel compared the raw level, so a source emitting "ERROR" lost its severity colour; the comparison is now lower-cased while the rendered text keeps its original case. Also documents that the renderer never branches on RenderOptions.JSON (the caller picks Line or JSONLine) and corrects replicaColorIndex's comment, which claimed to read a trailing digit run but folds digits from anywhere in the id. --- pkg/logs/render.go | 27 ++++++++++++---- pkg/logs/render_test.go | 68 +++++++++++++++++++++++++++++++++++++++++ 2 files changed, 89 insertions(+), 6 deletions(-) diff --git a/pkg/logs/render.go b/pkg/logs/render.go index dd7d715..ae5a2a7 100644 --- a/pkg/logs/render.go +++ b/pkg/logs/render.go @@ -3,6 +3,7 @@ package logs import ( "encoding/json" "fmt" + "strings" "time" "github.com/cli/cli/v2/pkg/iostreams" @@ -17,6 +18,8 @@ type RenderOptions struct { // Source.Caps().Replicas. ShowReplica bool // JSON emits one JSON object per line instead of the human format. + // The Renderer itself does not branch on this flag: callers decide the + // format by calling either Line or JSONLine. JSON bool // UTC prints timestamps in UTC instead of local time. UTC bool @@ -34,6 +37,8 @@ func NewRenderer(cs *iostreams.ColorScheme, opts RenderOptions) *Renderer { } // Line renders one entry in the human format, without a trailing newline. +// Line always renders the human format: it does not consult +// RenderOptions.JSON, so a caller wanting JSON must call JSONLine. func (r *Renderer) Line(e Entry) string { ts := e.Timestamp.In(time.Local) if r.opts.UTC { @@ -47,19 +52,27 @@ func (r *Renderer) Line(e Entry) string { return out } -// JSONLine renders one entry as a single-line JSON object. +// JSONLine renders one entry as a single-line JSON object. The timestamp is +// normalized to the same location Line would use, so RenderOptions.UTC applies +// to both formats. The caller's entry is not mutated. func (r *Renderer) JSONLine(e Entry) (string, error) { - b, err := json.Marshal(e) + out := e + out.Timestamp = e.Timestamp.In(time.Local) + if r.opts.UTC { + out.Timestamp = e.Timestamp.UTC() + } + b, err := json.Marshal(out) if err != nil { return "", fmt.Errorf("failed to encode log entry: %w", err) } return string(b), nil } -// colorLevel pads the level to a fixed width and colours it by severity. +// colorLevel pads the level to a fixed width and colours it by severity. The +// severity match is case-insensitive, but the level is rendered as supplied. func (r *Renderer) colorLevel(level string) string { padded := fmt.Sprintf("%-5s", level) - switch level { + switch strings.ToLower(level) { case "error", "fatal": return r.cs.Red(padded) case "warn": @@ -72,7 +85,7 @@ func (r *Renderer) colorLevel(level string) string { } // colorReplica colours the replica short id so lines from one replica are easy -// to follow. The colour is derived from the id's trailing digits so it is stable +// to follow. The colour is derived from the digits in the id so it is stable // without the renderer holding registry state. func (r *Renderer) colorReplica(shortID string) string { if shortID == "" { @@ -90,7 +103,9 @@ func (r *Renderer) colorReplica(shortID string) string { } } -// replicaColorIndex extracts the numeric part of a short id (r3 -> 3). +// replicaColorIndex folds every digit found anywhere in the short id into a +// single number, ignoring all non-digit runes (r3 -> 3, r1a2 -> 12). Ids with no +// digits yield 0. func replicaColorIndex(shortID string) int { n := 0 for _, c := range shortID { diff --git a/pkg/logs/render_test.go b/pkg/logs/render_test.go index 396e66e..f3c33cd 100644 --- a/pkg/logs/render_test.go +++ b/pkg/logs/render_test.go @@ -1,6 +1,8 @@ package logs import ( + "encoding/json" + "strings" "testing" "time" @@ -54,3 +56,69 @@ func TestRenderer_JSONLine(t *testing.T) { require.Contains(t, got, `"hostname":"host-1"`) require.Contains(t, got, `"replica":"r1"`) } + + +func TestRenderer_JSONLineHonoursUTC(t *testing.T) { + r := testRenderer(t, RenderOptions{JSON: true, UTC: true}) + zone := time.FixedZone("UTC+2", 2*60*60) + e := Entry{ + Timestamp: time.Date(2026, 8, 2, 16, 23, 1, 0, zone), + Level: "info", + Message: "hello", + } + got, err := r.JSONLine(e) + require.NoError(t, err) + + var decoded map[string]any + require.NoError(t, json.Unmarshal([]byte(got), &decoded)) + ts, ok := decoded["timestamp"].(string) + require.True(t, ok, "timestamp should be a JSON string, got %v", decoded["timestamp"]) + require.True(t, strings.HasSuffix(ts, "Z"), "timestamp %q should be rendered in UTC", ts) + require.Equal(t, "2026-08-02T14:23:01Z", ts, "the instant must be preserved, only the location changes") + + require.Equal(t, zone, e.Timestamp.Location(), "JSONLine must not mutate the caller's entry") +} + +func TestRenderer_LevelMatchIsCaseInsensitive(t *testing.T) { + r := testRenderer(t, RenderOptions{UTC: true}) + e := Entry{ + Timestamp: time.Date(2026, 8, 2, 14, 23, 1, 442000000, time.UTC), + Level: "ERROR", + Message: "boom", + } + line := r.Line(e) + require.Equal(t, "14:23:01.442 ERROR boom", line, "original level case is preserved") + require.Contains(t, line, "ERROR") +} + +func TestRenderer_LineLevels(t *testing.T) { + ts := time.Date(2026, 8, 2, 14, 23, 1, 442000000, time.UTC) + tests := []struct { + name string + level string + want string + }{ + {"fatal", "fatal", "14:23:01.442 fatal down"}, + {"debug", "debug", "14:23:01.442 debug down"}, + // Unknown levels take the default branch; padding never truncates. + {"unknown", "notice", "14:23:01.442 notice down"}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + r := testRenderer(t, RenderOptions{UTC: true}) + require.Equal(t, tt.want, r.Line(Entry{Timestamp: ts, Level: tt.level, Message: "down"})) + }) + } +} + +func TestRenderer_LineEmptyReplicaWithReplicaColumn(t *testing.T) { + r := testRenderer(t, RenderOptions{ShowReplica: true, UTC: true}) + e := Entry{ + Timestamp: time.Date(2026, 8, 2, 14, 23, 1, 442000000, time.UTC), + Level: "info", + Message: "no replica", + } + // Pins today's spacing for a missing replica id: the two-space placeholder + // plus the column separator. + require.Equal(t, "14:23:01.442 info no replica", r.Line(e)) +} From 292fc4ba6e2e5ef302e09acf092f27f5dfae868c Mon Sep 17 00:00:00 2001 From: Valdemar Pereira Date: Sun, 2 Aug 2026 21:31:20 +0100 Subject: [PATCH 08/20] test(logs): pin renderer severity colouring; use Muted over deprecated Gray The colouring tests built their scheme with iostreams.Test(), which yields ColorScheme{Enabled: false} and makes every colour method the identity function, so the case-insensitive level match and the whole severity mapping were unpinned. Add tests on a colour-enabled scheme that compare escape wrapping between error/ERROR and require the red, yellow and muted arms to stay distinct while unknown levels stay bare. Also replace the deprecated ColorScheme.Gray with Muted (appearance preserving: Muted falls back to Gray when Accessible is false) to clear staticcheck SA1019, pin the default local-time path for both Line and JSONLine with timezone-derived expectations, drop a vacuous non-mutation assertion, and gofmt the test file. --- pkg/logs/render.go | 7 ++- pkg/logs/render_test.go | 98 +++++++++++++++++++++++++++++++++++++++-- 2 files changed, 98 insertions(+), 7 deletions(-) diff --git a/pkg/logs/render.go b/pkg/logs/render.go index ae5a2a7..3096610 100644 --- a/pkg/logs/render.go +++ b/pkg/logs/render.go @@ -36,9 +36,8 @@ func NewRenderer(cs *iostreams.ColorScheme, opts RenderOptions) *Renderer { return &Renderer{cs: cs, opts: opts} } -// Line renders one entry in the human format, without a trailing newline. -// Line always renders the human format: it does not consult -// RenderOptions.JSON, so a caller wanting JSON must call JSONLine. +// Line renders one entry in the human format, without a trailing newline. It +// does not consult RenderOptions.JSON; a caller wanting JSON calls JSONLine. func (r *Renderer) Line(e Entry) string { ts := e.Timestamp.In(time.Local) if r.opts.UTC { @@ -78,7 +77,7 @@ func (r *Renderer) colorLevel(level string) string { case "warn": return r.cs.Yellow(padded) case "debug", "trace": - return r.cs.Gray(padded) + return r.cs.Muted(padded) default: return padded } diff --git a/pkg/logs/render_test.go b/pkg/logs/render_test.go index f3c33cd..edb8a53 100644 --- a/pkg/logs/render_test.go +++ b/pkg/logs/render_test.go @@ -2,6 +2,7 @@ package logs import ( "encoding/json" + "regexp" "strings" "testing" "time" @@ -16,6 +17,27 @@ func testRenderer(t *testing.T, opts RenderOptions) *Renderer { return NewRenderer(ios.ColorScheme(), opts) } +// colorRenderer returns a Renderer whose scheme actually emits ANSI escapes. +// iostreams.Test() yields ColorScheme{Enabled: false}, which makes every colour +// method the identity function and hides the severity mapping entirely, so the +// colouring tests build an enabled scheme (no 256-colour, no true-colour) +// directly. +func colorRenderer(t *testing.T, opts RenderOptions) *Renderer { + t.Helper() + return NewRenderer(&iostreams.ColorScheme{Enabled: true}, opts) +} + +// ansiPrefix is the start of every ANSI escape sequence. +const ansiPrefix = "\x1b[" + +var ansiSeqRE = regexp.MustCompile("\x1b\\[[0-9;]*m") + +// ansiCodes returns just the escape sequences in s, so two lines can be +// compared on colouring alone without asserting raw byte strings. +func ansiCodes(s string) []string { + return ansiSeqRE.FindAllString(s, -1) +} + func TestRenderer_LineWithoutReplicaColumn(t *testing.T) { r := testRenderer(t, RenderOptions{UTC: true}) e := Entry{ @@ -57,7 +79,6 @@ func TestRenderer_JSONLine(t *testing.T) { require.Contains(t, got, `"replica":"r1"`) } - func TestRenderer_JSONLineHonoursUTC(t *testing.T) { r := testRenderer(t, RenderOptions{JSON: true, UTC: true}) zone := time.FixedZone("UTC+2", 2*60*60) @@ -75,8 +96,6 @@ func TestRenderer_JSONLineHonoursUTC(t *testing.T) { require.True(t, ok, "timestamp should be a JSON string, got %v", decoded["timestamp"]) require.True(t, strings.HasSuffix(ts, "Z"), "timestamp %q should be rendered in UTC", ts) require.Equal(t, "2026-08-02T14:23:01Z", ts, "the instant must be preserved, only the location changes") - - require.Equal(t, zone, e.Timestamp.Location(), "JSONLine must not mutate the caller's entry") } func TestRenderer_LevelMatchIsCaseInsensitive(t *testing.T) { @@ -91,6 +110,79 @@ func TestRenderer_LevelMatchIsCaseInsensitive(t *testing.T) { require.Contains(t, line, "ERROR") } +// TestRenderer_LevelColourMatchIsCaseInsensitive is the test that genuinely +// pins strings.ToLower in colorLevel: with colour enabled, "ERROR" must receive +// the same escape wrapping as "error". Dropping the ToLower makes "ERROR" fall +// through to the uncoloured default branch and this test fails. +func TestRenderer_LevelColourMatchIsCaseInsensitive(t *testing.T) { + r := colorRenderer(t, RenderOptions{UTC: true}) + ts := time.Date(2026, 8, 2, 14, 23, 1, 442000000, time.UTC) + + lower := r.Line(Entry{Timestamp: ts, Level: "error", Message: "boom"}) + upper := r.Line(Entry{Timestamp: ts, Level: "ERROR", Message: "boom"}) + + require.Contains(t, lower, ansiPrefix, "colour-enabled scheme must emit escapes for error") + require.Equal(t, + strings.Replace(lower, "error", "LEVEL", 1), + strings.Replace(upper, "ERROR", "LEVEL", 1), + "ERROR must be coloured exactly like error; only the level text may differ") +} + +// TestRenderer_LevelColourSeverityArms pins the severity mapping: the red, +// yellow, muted and uncoloured arms must be distinguishable from one another. +func TestRenderer_LevelColourSeverityArms(t *testing.T) { + r := colorRenderer(t, RenderOptions{UTC: true}) + ts := time.Date(2026, 8, 2, 14, 23, 1, 442000000, time.UTC) + codesFor := func(level string) []string { + return ansiCodes(r.Line(Entry{Timestamp: ts, Level: level, Message: "x"})) + } + + errCodes := codesFor("error") + warnCodes := codesFor("warn") + debugCodes := codesFor("debug") + + require.NotEmpty(t, errCodes, "error must be coloured") + require.NotEmpty(t, warnCodes, "warn must be coloured") + require.NotEmpty(t, debugCodes, "debug must be coloured") + + require.NotEqual(t, errCodes, warnCodes, "warn must not share error's colour") + require.NotEqual(t, errCodes, debugCodes, "debug must not share error's colour") + require.NotEqual(t, warnCodes, debugCodes, "debug must not share warn's colour") + + require.Equal(t, errCodes, codesFor("fatal"), "fatal is grouped with error") + require.Equal(t, debugCodes, codesFor("trace"), "trace is grouped with debug") + + require.NotContains(t, r.Line(Entry{Timestamp: ts, Level: "notice", Message: "x"}), + ansiPrefix, "unknown levels are left uncoloured") +} + +// TestRenderer_LineDefaultsToLocalTime pins the UTC:false path, which every +// other test skips. The expectation is derived so it holds in any zone. +func TestRenderer_LineDefaultsToLocalTime(t *testing.T) { + r := testRenderer(t, RenderOptions{}) + ts := time.Date(2026, 8, 2, 16, 23, 1, 442000000, time.FixedZone("UTC+2", 2*60*60)) + e := Entry{Timestamp: ts, Level: "info", Message: "hello"} + + want := ts.In(time.Local).Format("15:04:05.000") + " info hello" + require.Equal(t, want, r.Line(e)) +} + +// TestRenderer_JSONLineDefaultsToLocalTime is the JSON counterpart: with +// UTC:false the timestamp is converted to time.Local, not left in the entry's +// own zone. +func TestRenderer_JSONLineDefaultsToLocalTime(t *testing.T) { + r := testRenderer(t, RenderOptions{JSON: true}) + ts := time.Date(2026, 8, 2, 16, 23, 1, 0, time.FixedZone("UTC+2", 2*60*60)) + + got, err := r.JSONLine(Entry{Timestamp: ts, Level: "info", Message: "hello"}) + require.NoError(t, err) + + wantTS, err := json.Marshal(ts.In(time.Local)) + require.NoError(t, err) + require.Contains(t, got, `"timestamp":`+string(wantTS), + "UTC:false must render the timestamp in time.Local") +} + func TestRenderer_LineLevels(t *testing.T) { ts := time.Date(2026, 8, 2, 14, 23, 1, 442000000, time.UTC) tests := []struct { From 8ee37f117682f288d601a5b5b4ab17f49bcd5cea Mon Sep 17 00:00:00 2001 From: Valdemar Pereira Date: Sun, 2 Aug 2026 21:41:43 +0100 Subject: [PATCH 09/20] feat(logs): add GraphQL log source with backfill-then-poll follow Adapts the Hasura datastore to logs.Source. History returns one newest-first page newer than Query.From, drops entries after Query.To, and rejects cursor paging with ErrPagingUnsupported since the backing query can only express "newer than". Follow applies Query.Limit to the initial backfill only and the fixed FollowPageSize to every later poll, fixing the old command's re-use of the history limit on every poll. --- pkg/logs/graphql_source.go | 115 ++++++++++++++++++++++++ pkg/logs/graphql_source_test.go | 155 ++++++++++++++++++++++++++++++++ 2 files changed, 270 insertions(+) create mode 100644 pkg/logs/graphql_source.go create mode 100644 pkg/logs/graphql_source_test.go diff --git a/pkg/logs/graphql_source.go b/pkg/logs/graphql_source.go new file mode 100644 index 0000000..b2334ab --- /dev/null +++ b/pkg/logs/graphql_source.go @@ -0,0 +1,115 @@ +package logs + +import ( + "context" + "fmt" + "time" + + "vonage-cloud-runtime-cli/pkg/api" +) + +// FollowPageSize is the per-poll limit used after the initial backfill, so +// --history bounds the backfill only (not every poll). +const FollowPageSize = 200 + +// LogLister is the subset of the datastore this source needs. +// cmdutil.DatastoreInterface satisfies it. +type LogLister interface { + ListLogsByInstanceID(ctx context.Context, id string, limit int, timestamp time.Time) ([]api.Log, error) +} + +// GraphQLSource reads logs from Hasura. Rows carry no hostname, so replica +// features are unavailable (Caps().Replicas == false), and the backing query can +// only express "newer than", so paging older than a cursor is unsupported. +type GraphQLSource struct { + lister LogLister + pollInterval time.Duration +} + +// NewGraphQLSource returns a source backed by the datastore. +func NewGraphQLSource(l LogLister, pollInterval time.Duration) *GraphQLSource { + if pollInterval <= 0 { + pollInterval = time.Second + } + return &GraphQLSource{lister: l, pollInterval: pollInterval} +} + +// Name identifies the source in messages and --source. +func (s *GraphQLSource) Name() string { return "graphql" } + +// Caps reports no replica data and no server push. +func (s *GraphQLSource) Caps() Caps { return Caps{Replicas: false, Push: false} } + +// History returns one page of entries newer than q.From, newest-first, dropping +// anything after q.To when set. +func (s *GraphQLSource) History(ctx context.Context, q Query) (Page, error) { + if q.Cursor != "" { + return Page{}, ErrPagingUnsupported + } + limit := q.Limit + if limit <= 0 { + limit = FollowPageSize + } + rows, err := s.lister.ListLogsByInstanceID(ctx, q.InstanceID, limit, q.From) + if err != nil { + return Page{}, fmt.Errorf("failed to list logs: %w", err) + } + entries := make([]Entry, 0, len(rows)) + for _, row := range rows { + if !q.To.IsZero() && row.Timestamp.After(q.To) { + continue + } + entries = append(entries, toEntry(row)) + } + return Page{Entries: entries, HasMore: false}, nil +} + +// Follow backfills once using q.Limit, then polls for newer entries, emitting +// them oldest-first on out until ctx is cancelled. +func (s *GraphQLSource) Follow(ctx context.Context, q Query, out chan<- Entry) error { + limit := q.Limit + if limit <= 0 { + limit = FollowPageSize + } + cursor := q.From + ticker := time.NewTicker(s.pollInterval) + defer ticker.Stop() + + for { + rows, err := s.lister.ListLogsByInstanceID(ctx, q.InstanceID, limit, cursor) + if err != nil { + if ctx.Err() != nil { + return nil + } + return fmt.Errorf("failed to list logs: %w", err) + } + // Datastore returns newest-first; emit oldest-first. + for i := len(rows) - 1; i >= 0; i-- { + select { + case out <- toEntry(rows[i]): + case <-ctx.Done(): + return nil + } + if rows[i].Timestamp.After(cursor) { + cursor = rows[i].Timestamp + } + } + limit = FollowPageSize + + select { + case <-ctx.Done(): + return nil + case <-ticker.C: + } + } +} + +// toEntry converts a datastore row into a normalized entry. +func toEntry(row api.Log) Entry { + return Entry{ + Timestamp: row.Timestamp, + Level: row.LogLevel, + Message: row.Message, + SourceType: row.SourceType, + } +} diff --git a/pkg/logs/graphql_source_test.go b/pkg/logs/graphql_source_test.go new file mode 100644 index 0000000..318f93f --- /dev/null +++ b/pkg/logs/graphql_source_test.go @@ -0,0 +1,155 @@ +package logs + +import ( + "context" + "errors" + "testing" + "time" + + "github.com/stretchr/testify/require" + + "vonage-cloud-runtime-cli/pkg/api" +) + +type fakeLister struct { + calls []time.Time + limits []int + pages [][]api.Log + err error +} + +func (f *fakeLister) ListLogsByInstanceID(_ context.Context, _ string, limit int, ts time.Time) ([]api.Log, error) { + f.calls = append(f.calls, ts) + f.limits = append(f.limits, limit) + if f.err != nil { + return nil, f.err + } + if len(f.pages) == 0 { + return nil, nil + } + page := f.pages[0] + f.pages = f.pages[1:] + return page, nil +} + +func TestGraphQLSource_CapsAndName(t *testing.T) { + s := NewGraphQLSource(&fakeLister{}, time.Second) + require.Equal(t, "graphql", s.Name()) + require.False(t, s.Caps().Replicas, "hasura rows carry no hostname") + require.False(t, s.Caps().Push, "graphql source polls") +} + +func TestGraphQLSource_HistoryReturnsNewestFirstAndFiltersTo(t *testing.T) { + t0 := time.Date(2026, 8, 2, 10, 0, 0, 0, time.UTC) + // Datastore returns newest-first. + lister := &fakeLister{pages: [][]api.Log{{ + {LogLevel: "info", SourceType: "application", Message: "newest", Timestamp: t0.Add(3 * time.Minute)}, + {LogLevel: "info", SourceType: "application", Message: "middle", Timestamp: t0.Add(2 * time.Minute)}, + {LogLevel: "info", SourceType: "application", Message: "oldest", Timestamp: t0.Add(1 * time.Minute)}, + }}} + s := NewGraphQLSource(lister, time.Second) + + page, err := s.History(context.Background(), Query{ + InstanceID: "inst-1", + From: t0, + To: t0.Add(2 * time.Minute), // excludes "newest" + Limit: 50, + }) + require.NoError(t, err) + require.False(t, page.HasMore) + require.Equal(t, "", page.Cursor) + require.Len(t, page.Entries, 2) + require.Equal(t, "middle", page.Entries[0].Message, "newest-first") + require.Equal(t, "oldest", page.Entries[1].Message) + require.Equal(t, t0, lister.calls[0], "From is passed as the _gt bound") + require.Equal(t, 50, lister.limits[0]) +} + +func TestGraphQLSource_HistoryRejectsCursor(t *testing.T) { + s := NewGraphQLSource(&fakeLister{}, time.Second) + _, err := s.History(context.Background(), Query{InstanceID: "i", Cursor: "123"}) + require.ErrorIs(t, err, ErrPagingUnsupported) +} + +func TestGraphQLSource_HistoryWrapsListerError(t *testing.T) { + sentinel := errors.New("boom") + s := NewGraphQLSource(&fakeLister{err: sentinel}, time.Second) + _, err := s.History(context.Background(), Query{InstanceID: "i"}) + require.ErrorIs(t, err, sentinel, "lister error must be wrapped with %w") +} + +func TestGraphQLSource_HistoryMapsAllEntryFields(t *testing.T) { + ts := time.Date(2026, 8, 2, 10, 0, 0, 0, time.UTC) + lister := &fakeLister{pages: [][]api.Log{{ + {LogLevel: "error", SourceType: "system", Message: "kaboom", Timestamp: ts}, + }}} + s := NewGraphQLSource(lister, time.Second) + + page, err := s.History(context.Background(), Query{InstanceID: "i"}) + require.NoError(t, err) + require.Equal(t, FollowPageSize, lister.limits[0], "a zero limit falls back to the page size") + require.Len(t, page.Entries, 1) + require.Equal(t, Entry{ + Timestamp: ts, + Level: "error", + Message: "kaboom", + SourceType: "system", + }, page.Entries[0]) +} + +func TestGraphQLSource_FollowUsesBackfillLimitOnceThenPageSize(t *testing.T) { + t0 := time.Date(2026, 8, 2, 10, 0, 0, 0, time.UTC) + lister := &fakeLister{pages: [][]api.Log{ + {{LogLevel: "info", Message: "first", Timestamp: t0}}, + {{LogLevel: "info", Message: "second", Timestamp: t0.Add(time.Second)}}, + }} + s := NewGraphQLSource(lister, time.Millisecond) + + ctx, cancel := context.WithCancel(context.Background()) + out := make(chan Entry, 8) + done := make(chan error, 1) + go func() { done <- s.Follow(ctx, Query{InstanceID: "i", Limit: 300}, out) }() + + require.Equal(t, "first", (<-out).Message) + require.Equal(t, "second", (<-out).Message) + cancel() + require.NoError(t, <-done) + + require.GreaterOrEqual(t, len(lister.limits), 2) + require.Equal(t, 300, lister.limits[0], "initial backfill uses Query.Limit") + require.Equal(t, FollowPageSize, lister.limits[1], "later polls use the fixed page size") + require.True(t, lister.calls[1].After(lister.calls[0]), "cursor advances") +} + +func TestGraphQLSource_FollowEmitsOldestFirstAndAdvancesToNewest(t *testing.T) { + t0 := time.Date(2026, 8, 2, 10, 0, 0, 0, time.UTC) + // Datastore returns newest-first; Follow must emit oldest-first. + lister := &fakeLister{pages: [][]api.Log{ + { + {LogLevel: "info", Message: "c", Timestamp: t0.Add(3 * time.Second)}, + {LogLevel: "info", Message: "b", Timestamp: t0.Add(2 * time.Second)}, + {LogLevel: "info", Message: "a", Timestamp: t0.Add(1 * time.Second)}, + }, + // Receiving this proves a second poll happened. + {{LogLevel: "info", Message: "marker", Timestamp: t0.Add(4 * time.Second)}}, + }} + s := NewGraphQLSource(lister, time.Millisecond) + + ctx, cancel := context.WithCancel(context.Background()) + out := make(chan Entry, 8) + done := make(chan error, 1) + go func() { done <- s.Follow(ctx, Query{InstanceID: "i", Limit: 0}, out) }() + + var got []string + for i := 0; i < 4; i++ { + got = append(got, (<-out).Message) + } + cancel() + require.NoError(t, <-done) + + require.Equal(t, []string{"a", "b", "c", "marker"}, got, "oldest-first within a page") + require.GreaterOrEqual(t, len(lister.calls), 2) + require.Equal(t, FollowPageSize, lister.limits[0], "a zero limit falls back to the page size") + require.True(t, lister.calls[0].IsZero(), "first poll uses Query.From") + require.Equal(t, t0.Add(3*time.Second), lister.calls[1], "cursor advances to newest timestamp seen") +} From f9006a3d0fa5865ca1dbd0a705df58a25b793abf Mon Sep 17 00:00:00 2001 From: Valdemar Pereira Date: Sun, 2 Aug 2026 21:58:47 +0100 Subject: [PATCH 10/20] test(logs): cover graphql source error, cursor and instance-id paths Nine surviving mutants in pkg/logs/graphql_source.go came from missing assertions, not from a production defect. Close the gaps: - Cover Follow's error path with a live context, so replacing the wrapped error with 'return nil' now fails. - Record the instance id in the fake lister and assert it in a History and a Follow test, so passing "" no longer survives. - Assert the wrapper prefix alongside ErrorIs, so a bare 'return err' fails. - Give the Follow cursor test a non-zero Query.From so the first recorded call discriminates q.From from time.Time{}. - Add a test where the lister cancels the context then fails, pinning cancellation taking precedence over the error. - Add a test that drives a poll cycle with a non-positive interval, so removing the NewGraphQLSource guard panics. Every Follow test now has a bounded lifetime (context timeout plus timeout-guarded channel reads), so a regression fails instead of hanging CI. Also document that this source ignores Query.SourceType and Query.Substring because the backing GraphQL query has no such parameters. --- pkg/logs/graphql_source.go | 4 + pkg/logs/graphql_source_test.go | 136 +++++++++++++++++++++++++++++--- 2 files changed, 127 insertions(+), 13 deletions(-) diff --git a/pkg/logs/graphql_source.go b/pkg/logs/graphql_source.go index b2334ab..895c67e 100644 --- a/pkg/logs/graphql_source.go +++ b/pkg/logs/graphql_source.go @@ -21,6 +21,10 @@ type LogLister interface { // GraphQLSource reads logs from Hasura. Rows carry no hostname, so replica // features are unavailable (Caps().Replicas == false), and the backing query can // only express "newer than", so paging older than a cursor is unsupported. +// +// Query.SourceType and Query.Substring are silently ignored by this source: the +// backing GraphQL query exposes no equivalent parameters, so callers that need +// those filters must apply them client-side to the returned entries. type GraphQLSource struct { lister LogLister pollInterval time.Duration diff --git a/pkg/logs/graphql_source_test.go b/pkg/logs/graphql_source_test.go index 318f93f..676c38c 100644 --- a/pkg/logs/graphql_source_test.go +++ b/pkg/logs/graphql_source_test.go @@ -11,16 +11,28 @@ import ( "vonage-cloud-runtime-cli/pkg/api" ) +// followTimeout bounds every Follow test so a regression fails instead of +// hanging CI. +const followTimeout = 5 * time.Second + type fakeLister struct { calls []time.Time limits []int + ids []string pages [][]api.Log err error + // onCall runs at the start of every call with the 1-based call number, + // letting a test cancel the context from inside the lister. + onCall func(call int) } -func (f *fakeLister) ListLogsByInstanceID(_ context.Context, _ string, limit int, ts time.Time) ([]api.Log, error) { +func (f *fakeLister) ListLogsByInstanceID(_ context.Context, id string, limit int, ts time.Time) ([]api.Log, error) { f.calls = append(f.calls, ts) f.limits = append(f.limits, limit) + f.ids = append(f.ids, id) + if f.onCall != nil { + f.onCall(len(f.calls)) + } if f.err != nil { return nil, f.err } @@ -32,6 +44,37 @@ func (f *fakeLister) ListLogsByInstanceID(_ context.Context, _ string, limit int return page, nil } +// startFollow runs Follow on a goroutine and returns its error channel. +func startFollow(ctx context.Context, s *GraphQLSource, q Query, out chan Entry) <-chan error { + done := make(chan error, 1) + go func() { done <- s.Follow(ctx, q, out) }() + return done +} + +// recvEntry reads one entry, failing rather than blocking forever. +func recvEntry(t *testing.T, out <-chan Entry) Entry { + t.Helper() + select { + case e := <-out: + return e + case <-time.After(followTimeout): + t.Fatal("timed out waiting for an entry from Follow") + return Entry{} + } +} + +// waitFollow waits for Follow to return, failing rather than hanging. +func waitFollow(t *testing.T, done <-chan error) error { + t.Helper() + select { + case err := <-done: + return err + case <-time.After(followTimeout): + t.Fatal("Follow did not return") + return nil + } +} + func TestGraphQLSource_CapsAndName(t *testing.T) { s := NewGraphQLSource(&fakeLister{}, time.Second) require.Equal(t, "graphql", s.Name()) @@ -63,6 +106,7 @@ func TestGraphQLSource_HistoryReturnsNewestFirstAndFiltersTo(t *testing.T) { require.Equal(t, "oldest", page.Entries[1].Message) require.Equal(t, t0, lister.calls[0], "From is passed as the _gt bound") require.Equal(t, 50, lister.limits[0]) + require.Equal(t, []string{"inst-1"}, lister.ids, "Query.InstanceID is passed through") } func TestGraphQLSource_HistoryRejectsCursor(t *testing.T) { @@ -76,6 +120,9 @@ func TestGraphQLSource_HistoryWrapsListerError(t *testing.T) { s := NewGraphQLSource(&fakeLister{err: sentinel}, time.Second) _, err := s.History(context.Background(), Query{InstanceID: "i"}) require.ErrorIs(t, err, sentinel, "lister error must be wrapped with %w") + // ErrorIs alone also passes for a bare `return err`; the prefix proves the + // error is actually wrapped with context. + require.Contains(t, err.Error(), "failed to list logs", "wrapper message must be preserved") } func TestGraphQLSource_HistoryMapsAllEntryFields(t *testing.T) { @@ -105,20 +152,22 @@ func TestGraphQLSource_FollowUsesBackfillLimitOnceThenPageSize(t *testing.T) { }} s := NewGraphQLSource(lister, time.Millisecond) - ctx, cancel := context.WithCancel(context.Background()) + ctx, cancel := context.WithTimeout(context.Background(), followTimeout) + defer cancel() out := make(chan Entry, 8) - done := make(chan error, 1) - go func() { done <- s.Follow(ctx, Query{InstanceID: "i", Limit: 300}, out) }() + done := startFollow(ctx, s, Query{InstanceID: "inst-follow", Limit: 300}, out) - require.Equal(t, "first", (<-out).Message) - require.Equal(t, "second", (<-out).Message) + require.Equal(t, "first", recvEntry(t, out).Message) + require.Equal(t, "second", recvEntry(t, out).Message) cancel() - require.NoError(t, <-done) + require.NoError(t, waitFollow(t, done)) require.GreaterOrEqual(t, len(lister.limits), 2) require.Equal(t, 300, lister.limits[0], "initial backfill uses Query.Limit") require.Equal(t, FollowPageSize, lister.limits[1], "later polls use the fixed page size") require.True(t, lister.calls[1].After(lister.calls[0]), "cursor advances") + require.Equal(t, "inst-follow", lister.ids[0], "Query.InstanceID is passed through") + require.Equal(t, "inst-follow", lister.ids[1], "Query.InstanceID is passed on every poll") } func TestGraphQLSource_FollowEmitsOldestFirstAndAdvancesToNewest(t *testing.T) { @@ -135,21 +184,82 @@ func TestGraphQLSource_FollowEmitsOldestFirstAndAdvancesToNewest(t *testing.T) { }} s := NewGraphQLSource(lister, time.Millisecond) - ctx, cancel := context.WithCancel(context.Background()) + ctx, cancel := context.WithTimeout(context.Background(), followTimeout) + defer cancel() out := make(chan Entry, 8) - done := make(chan error, 1) - go func() { done <- s.Follow(ctx, Query{InstanceID: "i", Limit: 0}, out) }() + // A non-zero From proves the initial cursor comes from Query.From. + done := startFollow(ctx, s, Query{InstanceID: "i", From: t0, Limit: 0}, out) var got []string for i := 0; i < 4; i++ { - got = append(got, (<-out).Message) + got = append(got, recvEntry(t, out).Message) } cancel() - require.NoError(t, <-done) + require.NoError(t, waitFollow(t, done)) require.Equal(t, []string{"a", "b", "c", "marker"}, got, "oldest-first within a page") require.GreaterOrEqual(t, len(lister.calls), 2) require.Equal(t, FollowPageSize, lister.limits[0], "a zero limit falls back to the page size") - require.True(t, lister.calls[0].IsZero(), "first poll uses Query.From") + require.Equal(t, t0, lister.calls[0], "first poll uses Query.From as the cursor") require.Equal(t, t0.Add(3*time.Second), lister.calls[1], "cursor advances to newest timestamp seen") } + +func TestGraphQLSource_FollowWrapsListerErrorWhenContextLive(t *testing.T) { + sentinel := errors.New("boom") + lister := &fakeLister{err: sentinel} + s := NewGraphQLSource(lister, time.Millisecond) + + // The context stays live: cancellation would legitimately swallow the error. + ctx, cancel := context.WithTimeout(context.Background(), followTimeout) + defer cancel() + out := make(chan Entry, 1) + done := startFollow(ctx, s, Query{InstanceID: "inst-err"}, out) + + err := waitFollow(t, done) + require.Error(t, err, "a lister error on a live context must surface") + require.ErrorIs(t, err, sentinel) + require.Contains(t, err.Error(), "failed to list logs", "wrapper message must be preserved") + require.NoError(t, ctx.Err(), "context must still be live for this to be meaningful") + require.Equal(t, []string{"inst-err"}, lister.ids, "Query.InstanceID is passed through") +} + +func TestGraphQLSource_FollowReturnsNilWhenContextCancelledBeforeError(t *testing.T) { + sentinel := errors.New("boom") + ctx, cancel := context.WithTimeout(context.Background(), followTimeout) + defer cancel() + + // The lister cancels the context and then fails, so cancellation wins. + lister := &fakeLister{err: sentinel, onCall: func(int) { cancel() }} + s := NewGraphQLSource(lister, time.Millisecond) + + out := make(chan Entry, 1) + done := startFollow(ctx, s, Query{InstanceID: "i"}, out) + + require.NoError(t, waitFollow(t, done), "cancellation takes precedence over the lister error") +} + +func TestGraphQLSource_NewGraphQLSourceFallsBackOnNonPositiveInterval(t *testing.T) { + for name, interval := range map[string]time.Duration{ + "zero": 0, + "negative": -time.Second, + } { + t.Run(name, func(t *testing.T) { + t0 := time.Date(2026, 8, 2, 10, 0, 0, 0, time.UTC) + lister := &fakeLister{pages: [][]api.Log{ + {{LogLevel: "info", Message: "only", Timestamp: t0}}, + }} + // A non-positive interval must be replaced: time.NewTicker would panic. + s := NewGraphQLSource(lister, interval) + + ctx, cancel := context.WithTimeout(context.Background(), followTimeout) + defer cancel() + out := make(chan Entry, 4) + done := startFollow(ctx, s, Query{InstanceID: "i"}, out) + + require.Equal(t, "only", recvEntry(t, out).Message, "one poll cycle completes without panicking") + cancel() + require.NoError(t, waitFollow(t, done)) + require.Greater(t, s.pollInterval, time.Duration(0), "non-positive intervals fall back to a valid duration") + }) + } +} From 7cae11c82fb2d950cb05d3689aaaf6cff8aa441e Mon Sep 17 00:00:00 2001 From: Valdemar Pereira Date: Sun, 2 Aug 2026 22:13:13 +0100 Subject: [PATCH 11/20] feat(log): rebuild instance log on pkg/logs with new time, filter and output flags Adds --since/--from/--to, --grep/--exclude, --buffer, --json, --reverse, --utc and --source. Fixes --follow being bounded by the global --timeout, and --history being re-applied on every poll instead of bounding the backfill. An unrecognised --log-level is now an error rather than silently discarding every line, so the old fail-closed behaviour is preserved explicitly. --- vcr/instance/log/log.go | 381 +++++++++++++++++++++++------------ vcr/instance/log/log_test.go | 324 +++++++++++++++++------------ 2 files changed, 440 insertions(+), 265 deletions(-) diff --git a/vcr/instance/log/log.go b/vcr/instance/log/log.go index b829a8b..244924e 100644 --- a/vcr/instance/log/log.go +++ b/vcr/instance/log/log.go @@ -6,192 +6,332 @@ import ( "fmt" "os" "os/signal" + "strings" "syscall" "time" "github.com/MakeNowJust/heredoc" - "github.com/cli/cli/v2/pkg/iostreams" "github.com/spf13/cobra" "vonage-cloud-runtime-cli/pkg/api" "vonage-cloud-runtime-cli/pkg/cmdutil" + "vonage-cloud-runtime-cli/pkg/logs" ) const ( + // TickerInterval is how often the graphql source polls while following. TickerInterval = 1 * time.Second - - // Log level constants - LogLevelTrace = 1 - LogLevelDebug = 2 - LogLevelInfo = 3 - LogLevelWarn = 4 - LogLevelError = 5 - LogLevelFatal = 6 - - // Default history limit + // DefaultHistoryLimit is the initial backfill size. DefaultHistoryLimit = 300 ) -var ( - logLevelMap = map[string]int{ - "trace": LogLevelTrace, - "debug": LogLevelDebug, - "info": LogLevelInfo, - "warn": LogLevelWarn, - "error": LogLevelError, - "fatal": LogLevelFatal, - } -) - type Options struct { cmdutil.Factory InstanceID string ProjectName string InstanceName string - LogLevel string - SourceType string - Limit int - Follow bool + + // time selection + Since time.Duration + From string + To string + Limit int + + // filters + LogLevel string + SourceType string + Grep string + Exclude string + Replicas string + + // output + BufferSize int + JSONOut bool + Reverse bool + UTC bool + + // source selection (Phase 3 adds "stream") + SourceName string + Follow bool } func NewCmdInstanceLog(f cmdutil.Factory) *cobra.Command { - opts := Options{ - Factory: f, - } + return newLogCmd(f, "log", []string{"logs"}) +} + +// NewCmdLogs returns the same command registered at the top level as "vcr logs". +func NewCmdLogs(f cmdutil.Factory) *cobra.Command { + return newLogCmd(f, "logs", nil) +} + +func newLogCmd(f cmdutil.Factory, use string, aliases []string) *cobra.Command { + opts := Options{Factory: f} cmd := &cobra.Command{ - Use: "log", - Aliases: []string{"logs"}, + Use: use, + Aliases: aliases, Short: "Fetch logs from a deployed VCR instance", Long: heredoc.Doc(`Fetch logs from a deployed VCR instance. - By default, the command retrieves the last N log entries (controlled by --history) - and exits. Use --follow (-f) to continuously stream new log entries until you - press Ctrl+C. + By default the command prints recent log entries and exits. Use --follow (-f) + to keep streaming new entries until you press Ctrl+C. IDENTIFYING THE INSTANCE - You can identify the instance using either: - • --id: The unique instance UUID - • --project-name + --instance-name: The combination from your manifest - - LOG LEVELS - Filter logs by severity level (shows specified level and above): - • trace - Most verbose, includes all logs - • debug - Debug information and above - • info - Informational messages and above - • warn - Warnings and above - • error - Errors and above - • fatal - Only fatal errors - - SOURCE TYPES - Filter logs by their source: - • application - Logs from your application code - • provider - Logs from VCR platform services - - OUTPUT FORMAT - Each log line shows: [timestamp] [source_type] message - Example: 2024-01-15T10:30:00Z [application] Server started on port 3000 + • --id: the instance UUID + • --project-name + --instance-name: the combination from your manifest + + SELECTING A TIME RANGE + • --since 15m|2h start from a relative point in the past + • --from/--to RFC3339 an explicit window + • --history N limit the initial backfill (default 300) + --since and --from are mutually exclusive. --history composes with a + window: the last N entries within it. + + FILTERING + • --log-level minimum severity: trace, debug, info, warn, error, fatal + • --source-type application | provider + • --grep show only messages matching a Go RE2 regex + • --exclude hide messages matching a Go RE2 regex + Use (?i) inside a pattern for case-insensitive matching. + + OUTPUT + Each line is: HH:MM:SS.mmm level message + --json prints one JSON object per line for scripting. `), Args: cobra.MaximumNArgs(0), Example: heredoc.Doc(` - # Print the last logs by project and instance name (default, exits after output) - $ vcr instance log --project-name my-app --instance-name dev - 2024-01-15T10:30:00Z [application] Server started on port 3000 - 2024-01-15T10:30:01Z [application] Connected to database - - # Print the last logs by instance ID - $ vcr instance log --id 12345678-1234-1234-1234-123456789abc + # Print recent logs and exit + $ vcr logs --project-name my-app --instance-name dev - # Continuously stream new logs (press Ctrl+C to stop) - $ vcr instance log -p my-app -n dev --follow - $ vcr instance log -p my-app -n dev -f + # Follow new logs (Ctrl+C to stop) + $ vcr logs -p my-app -n dev --follow - # Print the last 500 log entries and exit - $ vcr instance log -p my-app -n dev --history 500 + # The last 15 minutes, errors only + $ vcr logs -p my-app -n dev --since 15m --log-level error - # Filter to show only errors and above - $ vcr instance log -p my-app -n dev --log-level error + # An explicit window + $ vcr logs -i 12345678-1234-1234-1234-123456789abc --from 2026-08-02T10:00:00Z --to 2026-08-02T11:00:00Z - # Show only application logs (exclude provider logs) - $ vcr instance log -p my-app -n dev --source-type application - - # Combine filters with follow - $ vcr instance log -p my-app -n dev -l warn -s application -f + # Only payment failures, excluding health checks, as JSON + $ vcr logs -p my-app -n dev --grep 'pay.*502' --exclude '/health' --json `), RunE: func(_ *cobra.Command, _ []string) error { - ctx, cancel := context.WithDeadline(context.Background(), opts.Deadline()) - defer cancel() - - return runLog(ctx, &opts) + return runLog(&opts) }, } cmd.Flags().StringVarP(&opts.InstanceID, "id", "i", "", "Instance UUID (alternative to project-name + instance-name)") - cmd.Flags().IntVarP(&opts.Limit, "history", "", DefaultHistoryLimit, "Number of historical log entries to fetch initially (default: 300)") cmd.Flags().StringVarP(&opts.ProjectName, "project-name", "p", "", "Project name (requires --instance-name)") cmd.Flags().StringVarP(&opts.InstanceName, "instance-name", "n", "", "Instance name (requires --project-name)") + cmd.Flags().IntVarP(&opts.Limit, "history", "", DefaultHistoryLimit, "Number of historical log entries to fetch initially") + cmd.Flags().DurationVarP(&opts.Since, "since", "", 0, "Start from this long ago (e.g. 15m, 2h)") + cmd.Flags().StringVarP(&opts.From, "from", "", "", "Window start (RFC3339)") + cmd.Flags().StringVarP(&opts.To, "to", "", "", "Window end (RFC3339)") cmd.Flags().StringVarP(&opts.LogLevel, "log-level", "l", "", "Minimum log level: trace, debug, info, warn, error, fatal") cmd.Flags().StringVarP(&opts.SourceType, "source-type", "s", "", "Filter by source: application, provider") + cmd.Flags().StringVarP(&opts.Grep, "grep", "g", "", "Show only messages matching this RE2 regex") + cmd.Flags().StringVarP(&opts.Exclude, "exclude", "v", "", "Hide messages matching this RE2 regex") + cmd.Flags().StringVarP(&opts.Replicas, "replica", "", "", "Comma-separated replica ids or hostnames (requires a replica-capable source)") + cmd.Flags().IntVarP(&opts.BufferSize, "buffer", "", logs.DefaultBufferSize, "Maximum log entries retained in memory") + cmd.Flags().BoolVarP(&opts.JSONOut, "json", "", false, "Print one JSON object per line") + cmd.Flags().BoolVarP(&opts.Reverse, "reverse", "", false, "Reverse the default ordering for the current mode") + cmd.Flags().BoolVarP(&opts.UTC, "utc", "", false, "Print timestamps in UTC") + cmd.Flags().StringVarP(&opts.SourceName, "source", "", "auto", "Log source: auto, graphql") cmd.Flags().BoolVarP(&opts.Follow, "follow", "f", false, "Continuously stream new log entries (press Ctrl+C to stop)") return cmd } -func runLog(ctx context.Context, opts *Options) error { +// buildQueryAndFilter converts flags into a source query and a filter, failing +// fast on contradictory or malformed input. +func buildQueryAndFilter(opts *Options) (logs.Query, *logs.Filter, error) { + if opts.Since > 0 && opts.From != "" { + return logs.Query{}, nil, fmt.Errorf("--since and --from are mutually exclusive") + } + + q := logs.Query{ + InstanceID: opts.InstanceID, + Limit: opts.Limit, + SourceType: opts.SourceType, + } + switch { + case opts.Since > 0: + q.From = time.Now().Add(-opts.Since) + case opts.From != "": + t, err := time.Parse(time.RFC3339, opts.From) + if err != nil { + return logs.Query{}, nil, fmt.Errorf("invalid --from value %q: expected RFC3339", opts.From) + } + q.From = t + } + if opts.To != "" { + t, err := time.Parse(time.RFC3339, opts.To) + if err != nil { + return logs.Query{}, nil, fmt.Errorf("invalid --to value %q: expected RFC3339", opts.To) + } + q.To = t + } + + f := &logs.Filter{SourceType: opts.SourceType} + if opts.LogLevel != "" { + lvl, ok := logs.ParseLevel(opts.LogLevel) + if !ok { + return logs.Query{}, nil, fmt.Errorf("invalid --log-level %q: want one of %s", opts.LogLevel, strings.Join(logs.LevelNames(), ", ")) + } + f.MinLevel = lvl + } + if err := f.SetInclude(opts.Grep); err != nil { + return logs.Query{}, nil, err + } + if err := f.SetExclude(opts.Exclude); err != nil { + return logs.Query{}, nil, err + } + return q, f, nil +} + +// newSource picks the log source. Phase 3 adds the SSE-backed "stream" source. +func newSource(opts *Options) (logs.Source, error) { + switch opts.SourceName { + case "", "auto", "graphql": + return logs.NewGraphQLSource(opts.Datastore(), TickerInterval), nil + default: + return nil, fmt.Errorf("unknown --source %q: want auto or graphql", opts.SourceName) + } +} + +func runLog(opts *Options) error { io := opts.IOStreams() if err := cmdutil.ValidateFlags(opts.InstanceID, opts.InstanceName, opts.ProjectName); err != nil { return fmt.Errorf("failed to validate flags: %w", err) } - inst, err := getInstance(ctx, opts) + q, filter, err := buildQueryAndFilter(opts) if err != nil { - return fmt.Errorf("failed to get instance: %w", err) + return fmt.Errorf("failed to validate flags: %w", err) + } + + src, err := newSource(opts) + if err != nil { + return fmt.Errorf("failed to select log source: %w", err) + } + if opts.Replicas != "" && !src.Caps().Replicas { + return fmt.Errorf("failed to validate flags: --replica needs a replica-capable log source; the %q source does not provide replica information", src.Name()) } + // Instance resolution is bounded by the global deadline. + lookupCtx, cancelLookup := context.WithDeadline(context.Background(), opts.Deadline()) + defer cancelLookup() + inst, err := getInstance(lookupCtx, opts) + if err != nil { + return fmt.Errorf("failed to get instance: %w", err) + } opts.InstanceID = inst.ID + q.InstanceID = inst.ID + + renderer := logs.NewRenderer(io.ColorScheme(), logs.RenderOptions{ + ShowReplica: src.Caps().Replicas, + JSON: opts.JSONOut, + UTC: opts.UTC, + }) + buf := logs.NewBuffer(opts.BufferSize) + registry := logs.NewRegistry() - // Without --follow just print the historical logs and exit. if !opts.Follow { - fetchLogs(io, opts, time.Time{}) - return nil + return runHistory(src, opts, q, filter, renderer, buf, registry) } + return runFollow(src, opts, q, filter, renderer, buf, registry) +} - ticker := time.NewTicker(TickerInterval) - defer ticker.Stop() - lastTimestamp := time.Time{} +// runHistory prints one window and exits. Default ordering is chronological. +func runHistory(src logs.Source, opts *Options, q logs.Query, filter *logs.Filter, renderer *logs.Renderer, buf *logs.Buffer, registry *logs.Registry) error { + io := opts.IOStreams() + ctx, cancel := context.WithDeadline(context.Background(), opts.Deadline()) + defer cancel() + + page, err := src.History(ctx, q) + if err != nil { + return fmt.Errorf("failed to fetch logs: %w", err) + } + + // History returns newest-first; print chronologically unless --reverse. + ordered := make([]logs.Entry, 0, len(page.Entries)) + if opts.Reverse { + ordered = append(ordered, page.Entries...) + } else { + for i := len(page.Entries) - 1; i >= 0; i-- { + ordered = append(ordered, page.Entries[i]) + } + } + + shown := 0 + for _, e := range ordered { + e.ReplicaID = registry.Ensure(e.Hostname).ShortID + buf.Add(e) + if !filter.Match(e) { + continue + } + emit(opts, renderer, e) + shown++ + } + if shown == 0 { + c := io.ColorScheme() + fmt.Fprintf(io.ErrOut, "%s no matching log entries in range\n", c.WarningIcon()) + } + return nil +} + +// runFollow streams until interrupted. The follow loop is bounded by SIGINT / +// SIGTERM, not by the global --timeout. +func runFollow(src logs.Source, opts *Options, q logs.Query, filter *logs.Filter, renderer *logs.Renderer, buf *logs.Buffer, registry *logs.Registry) error { + io := opts.IOStreams() + c := io.ColorScheme() + + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() interrupt := make(chan os.Signal, 1) signal.Notify(interrupt, os.Interrupt, syscall.SIGTERM) + defer signal.Stop(interrupt) + + entries := make(chan logs.Entry, 256) + errCh := make(chan error, 1) + go func() { errCh <- src.Follow(ctx, q, entries) }() for { select { - case <-ticker.C: - lastTimestamp = fetchLogs(io, opts, lastTimestamp) case <-interrupt: - fmt.Println("Interrupt received, stopping...") + fmt.Fprintf(io.ErrOut, "\n%s stopped\n", c.SuccessIcon()) + return nil + case err := <-errCh: + if err != nil { + return fmt.Errorf("failed to stream logs: %w", err) + } return nil + case e := <-entries: + e.ReplicaID = registry.Ensure(e.Hostname).ShortID + buf.Add(e) + if !filter.Match(e) { + continue + } + emit(opts, renderer, e) } } } -func fetchLogs(out *iostreams.IOStreams, opts *Options, lastTimestamp time.Time) time.Time { - c := out.ColorScheme() - ctx, cancel := context.WithDeadline(context.Background(), time.Now().Add(opts.Timeout())) - defer cancel() - logs, err := opts.Datastore().ListLogsByInstanceID(ctx, opts.InstanceID, opts.Limit, lastTimestamp) - if err != nil { - fmt.Fprintf(out.ErrOut, "%s Error fetching logs: %v\n", c.WarningIcon(), err) - return lastTimestamp - } - - for i := len(logs) - 1; i >= 0; i-- { - log := logs[i] - printLogs(out, opts, log) - lastTimestamp = log.Timestamp +// emit writes one entry in the configured format. +func emit(opts *Options, renderer *logs.Renderer, e logs.Entry) { + io := opts.IOStreams() + if opts.JSONOut { + line, err := renderer.JSONLine(e) + if err != nil { + fmt.Fprintf(io.ErrOut, "%s %v\n", io.ColorScheme().WarningIcon(), err) + return + } + fmt.Fprintln(io.Out, line) + return } - - return lastTimestamp + fmt.Fprintln(io.Out, renderer.Line(e)) } func getInstance(ctx context.Context, opts *Options) (api.Instance, error) { @@ -214,30 +354,3 @@ func getInstance(ctx context.Context, opts *Options) (api.Instance, error) { } return inst, nil } - -func printLogs(out *iostreams.IOStreams, opts *Options, log api.Log) { - switch { - case opts.SourceType != "" && opts.LogLevel != "": - if opts.SourceType != log.SourceType || logLevelBelowThresholdOrInvalid(opts.LogLevel, log.LogLevel) { - return - } - case opts.SourceType != "": - if opts.SourceType != log.SourceType { - return - } - case opts.LogLevel != "": - if logLevelBelowThresholdOrInvalid(opts.LogLevel, log.LogLevel) { - return - } - } - fmt.Fprintf(out.Out, "%s [%s] %s\n", log.Timestamp.In(time.Local).Format(time.RFC3339), log.SourceType, log.Message) -} - -func logLevelBelowThresholdOrInvalid(thresholdLoglevel, loglevel string) bool { - if thresholdNum, thresholdOk := logLevelMap[thresholdLoglevel]; thresholdOk { - if logLevelNum, logLevelOk := logLevelMap[loglevel]; logLevelOk { - return logLevelNum < thresholdNum - } - } - return true -} diff --git a/vcr/instance/log/log_test.go b/vcr/instance/log/log_test.go index 9575b0d..62df6f7 100644 --- a/vcr/instance/log/log_test.go +++ b/vcr/instance/log/log_test.go @@ -2,9 +2,11 @@ package log import ( "bytes" + "context" "errors" "io" "os" + "strings" "testing" "time" @@ -14,10 +16,64 @@ import ( "github.com/stretchr/testify/require" "vonage-cloud-runtime-cli/pkg/api" + "vonage-cloud-runtime-cli/pkg/logs" "vonage-cloud-runtime-cli/testutil" "vonage-cloud-runtime-cli/testutil/mocks" ) +func Test_buildQueryAndFilter(t *testing.T) { + t.Run("since sets From", func(t *testing.T) { + opts := &Options{Since: 15 * time.Minute, Limit: 300} + q, _, err := buildQueryAndFilter(opts) + require.NoError(t, err) + require.WithinDuration(t, time.Now().Add(-15*time.Minute), q.From, 5*time.Second) + require.Equal(t, 300, q.Limit) + }) + + t.Run("since and from are mutually exclusive", func(t *testing.T) { + opts := &Options{Since: time.Minute, From: "2026-08-02T10:00:00Z"} + _, _, err := buildQueryAndFilter(opts) + require.Error(t, err) + require.Contains(t, err.Error(), "mutually exclusive") + }) + + t.Run("invalid from is rejected", func(t *testing.T) { + opts := &Options{From: "not-a-time"} + _, _, err := buildQueryAndFilter(opts) + require.Error(t, err) + require.Contains(t, err.Error(), "--from") + }) + + t.Run("invalid grep is rejected", func(t *testing.T) { + opts := &Options{Grep: "("} + _, _, err := buildQueryAndFilter(opts) + require.Error(t, err) + }) + + t.Run("filters are populated", func(t *testing.T) { + opts := &Options{LogLevel: "warn", SourceType: "application", Grep: "boom", Exclude: "health"} + _, f, err := buildQueryAndFilter(opts) + require.NoError(t, err) + require.Equal(t, logs.LevelWarn, f.MinLevel) + require.Equal(t, "application", f.SourceType) + require.True(t, f.Match(logs.Entry{Level: "error", Message: "boom", SourceType: "application"})) + require.False(t, f.Match(logs.Entry{Level: "error", Message: "boom health", SourceType: "application"})) + }) + + t.Run("unknown log level is rejected", func(t *testing.T) { + opts := &Options{LogLevel: "loud"} + _, _, err := buildQueryAndFilter(opts) + require.Error(t, err) + require.Contains(t, err.Error(), "--log-level") + }) + + t.Run("replica flag needs a replica-capable source", func(t *testing.T) { + opts := &Options{Replicas: "r1"} + _, _, err := buildQueryAndFilter(opts) + require.NoError(t, err, "parsing succeeds; capability is checked against the source") + }) +} + func TestLog(t *testing.T) { type mock struct { LogListLogsByInstanceIDTimes int @@ -87,7 +143,57 @@ func TestLog(t *testing.T) { LogGetInstanceByIDReturnErr: nil, }, want: want{ - stdout: "[application] hello", + stdout: "hello", + }, + }, + { + name: "json-output-emits-one-object-per-line", + cli: "--id=abc-123 --json", + mock: mock{ + LogListLogsByInstanceIDTimes: 1, + LogGetInstanceByIDTimes: 1, + LogReturnInstance: api.Instance{ID: "abc-123"}, + LogInstanceID: "abc-123", + LogReturnLogs: []api.Log{{Timestamp: time.Now(), SourceType: "application", LogLevel: "info", Message: "hello"}}, + }, + want: want{ + stdout: `"message":"hello"`, + }, + }, + { + name: "unknown-log-level-fails-closed", + cli: "--id=abc-123 --log-level=loud", + mock: mock{ + LogListLogsByInstanceIDTimes: 0, + LogGetInstanceByIDTimes: 0, + }, + want: want{ + errMsg: `failed to validate flags: invalid --log-level "loud": want one of trace, debug, info, warn, error, fatal`, + }, + }, + { + name: "replica-flag-rejected-for-graphql-source", + cli: "--id=abc-123 --replica=r1", + mock: mock{ + LogListLogsByInstanceIDTimes: 0, + LogGetInstanceByIDTimes: 0, + }, + want: want{ + errMsg: `--replica needs a replica-capable log source; the "graphql" source does not provide replica information`, + }, + }, + { + name: "log-level-filters-out-lower-severity", + cli: "--id=abc-123 --log-level=error", + mock: mock{ + LogListLogsByInstanceIDTimes: 1, + LogGetInstanceByIDTimes: 1, + LogReturnInstance: api.Instance{ID: "abc-123"}, + LogInstanceID: "abc-123", + LogReturnLogs: []api.Log{{Timestamp: time.Now(), SourceType: "application", LogLevel: "info", Message: "quiet"}}, + }, + want: want{ + stderr: "! no matching log entries in range\n", }, }, { @@ -167,135 +273,6 @@ func TestLog(t *testing.T) { } } -func Test_fetchLogs(t *testing.T) { - type mock struct { - LogListLogsByInstanceIDTimes int - LogListLogsByInstanceIDReturnErr error - LogReturnLogs []api.Log - } - type want struct { - stdout string - stderr string - } - tests := []struct { - name string - mock mock - want want - }{ - { - name: "Test with error", - mock: mock{LogListLogsByInstanceIDTimes: 1, LogListLogsByInstanceIDReturnErr: errors.New("failed to list logs"), LogReturnLogs: nil}, - want: want{stderr: "! Error fetching logs: failed to list logs\n"}, - }, - { - name: "Test without error", - mock: mock{LogListLogsByInstanceIDTimes: 1, LogListLogsByInstanceIDReturnErr: nil, LogReturnLogs: []api.Log{{Timestamp: time.Now(), SourceType: "application", Message: "test"}}}, - want: want{stdout: time.Now().In(time.Local).Format(time.RFC3339) + " [application] test\n"}, - }, - } - - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - - ctrl := gomock.NewController(t) - - datastoreMock := mocks.NewMockDatastoreInterface(ctrl) - datastoreMock.EXPECT().ListLogsByInstanceID(gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any()). - Times(tt.mock.LogListLogsByInstanceIDTimes). - Return(tt.mock.LogReturnLogs, tt.mock.LogListLogsByInstanceIDReturnErr) - - ios, _, stdout, stderr := iostreams.Test() - lastTimestamp := time.Now() - - f := testutil.DefaultFactoryMock(t, ios, nil, nil, datastoreMock, nil, nil, nil) - - opts := &Options{ - Factory: f, - } - - fetchLogs(ios, opts, lastTimestamp) - - cmdOut := &testutil.CmdOut{ - OutBuf: stdout, - ErrBuf: stderr, - } - if tt.want.stderr != "" { - require.Equal(t, tt.want.stderr, cmdOut.Stderr()) - return - } - require.Equal(t, tt.want.stdout, cmdOut.String()) - }) - } -} - -func Test_printLogs(t *testing.T) { - - type mock struct { - LogSourceType string - LogLogLevel string - } - type want struct { - stdout string - } - tests := []struct { - name string - mock mock - want want - }{ - { - name: "Test with source type", - mock: mock{LogSourceType: "application", LogLogLevel: ""}, - want: want{stdout: time.Now().In(time.Local).Format(time.RFC3339) + " [application] test\n"}, - }, - { - name: "Test with info log level", - mock: mock{LogSourceType: "", LogLogLevel: "info"}, - want: want{stdout: time.Now().In(time.Local).Format(time.RFC3339) + " [application] test\n"}, - }, - { - name: "Test with warn log level", - mock: mock{LogSourceType: "", LogLogLevel: "warn"}, - want: want{stdout: ""}, - }, - { - name: "Test with source type and log level", - mock: mock{LogSourceType: "application", LogLogLevel: "info"}, - want: want{stdout: time.Now().In(time.Local).Format(time.RFC3339) + " [application] test\n"}, - }, - { - name: "Test without source type and log level", - mock: mock{LogSourceType: "", LogLogLevel: ""}, - want: want{stdout: time.Now().In(time.Local).Format(time.RFC3339) + " [application] test\n"}, - }, - { - name: "Test with log level not exist", - mock: mock{LogSourceType: "", LogLogLevel: "log-level-not-exist"}, - want: want{stdout: ""}, - }, - { - name: "Test with source type not exist", - mock: mock{LogSourceType: "provider", LogLogLevel: "info"}, - want: want{stdout: ""}, - }, - } - - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { - - ios, _, stdout, _ := iostreams.Test() - - opts := &Options{ - SourceType: tt.mock.LogSourceType, - LogLevel: tt.mock.LogLogLevel, - } - - printLogs(ios, opts, api.Log{Timestamp: time.Now(), SourceType: "application", Message: "test", LogLevel: "info"}) - - require.Equal(t, tt.want.stdout, stdout.String()) - }) - } -} - func TestLog_Follow(t *testing.T) { ctrl := gomock.NewController(t) @@ -340,5 +317,90 @@ func TestLog_Follow(t *testing.T) { _, err = cmd.ExecuteC() require.NoError(t, err, "follow should exit cleanly on interrupt") require.GreaterOrEqual(t, callCount, 2, "logs should have been fetched at least twice") - require.Contains(t, stdout.String(), "[application] streaming") + require.Contains(t, stdout.String(), "streaming") +} + +// fakeFollowSource records the context handed to Follow so a test can assert the +// follow loop is not bounded by the global --timeout deadline. It also serves a +// canned History page. +type fakeFollowSource struct { + hadDeadline bool + followErr error + historyPage logs.Page +} + +func (s *fakeFollowSource) Name() string { return "fake" } +func (s *fakeFollowSource) Caps() logs.Caps { return logs.Caps{} } + +func (s *fakeFollowSource) History(_ context.Context, _ logs.Query) (logs.Page, error) { + return s.historyPage, nil +} + +func (s *fakeFollowSource) Follow(ctx context.Context, _ logs.Query, _ chan<- logs.Entry) error { + _, s.hadDeadline = ctx.Deadline() + return s.followErr +} + +// Test_runFollow_isNotBoundedByGlobalTimeout pins defect fix 1: deriving the +// follow context from opts.Deadline() used to kill --follow after --timeout. +func Test_runFollow_isNotBoundedByGlobalTimeout(t *testing.T) { + ios, _, _, _ := iostreams.Test() + f := testutil.DefaultFactoryMock(t, ios, nil, nil, nil, nil, nil, nil) + opts := &Options{Factory: f, Follow: true, BufferSize: 10} + + src := &fakeFollowSource{} + err := runFollow(src, opts, logs.Query{}, &logs.Filter{}, + logs.NewRenderer(ios.ColorScheme(), logs.RenderOptions{}), logs.NewBuffer(10), logs.NewRegistry()) + + require.NoError(t, err) + require.False(t, src.hadDeadline, "follow context must not carry the global --timeout deadline") +} + +func Test_runFollow_wrapsSourceError(t *testing.T) { + ios, _, _, _ := iostreams.Test() + f := testutil.DefaultFactoryMock(t, ios, nil, nil, nil, nil, nil, nil) + opts := &Options{Factory: f, Follow: true, BufferSize: 10} + + src := &fakeFollowSource{followErr: errors.New("transport died")} + err := runFollow(src, opts, logs.Query{}, &logs.Filter{}, + logs.NewRenderer(ios.ColorScheme(), logs.RenderOptions{}), logs.NewBuffer(10), logs.NewRegistry()) + + require.Error(t, err) + require.Contains(t, err.Error(), "failed to stream logs: transport died") +} + +// Test_runHistory_ordering pins that a history page (newest-first from the +// source) is printed chronologically by default and newest-first with --reverse. +func Test_runHistory_ordering(t *testing.T) { + base := time.Date(2026, 8, 2, 10, 0, 0, 0, time.UTC) + newestFirst := logs.Page{Entries: []logs.Entry{ + {Timestamp: base.Add(2 * time.Minute), Level: "info", Message: "third"}, + {Timestamp: base.Add(1 * time.Minute), Level: "info", Message: "second"}, + {Timestamp: base, Level: "info", Message: "first"}, + }} + + run := func(t *testing.T, reverse bool) string { + t.Helper() + ios, _, stdout, _ := iostreams.Test() + f := testutil.DefaultFactoryMock(t, ios, nil, nil, nil, nil, nil, nil) + opts := &Options{Factory: f, BufferSize: 10, Reverse: reverse} + src := &fakeFollowSource{historyPage: newestFirst} + + err := runHistory(src, opts, logs.Query{}, &logs.Filter{}, + logs.NewRenderer(ios.ColorScheme(), logs.RenderOptions{}), logs.NewBuffer(10), logs.NewRegistry()) + require.NoError(t, err) + return stdout.String() + } + + t.Run("default is chronological", func(t *testing.T) { + out := run(t, false) + require.Less(t, strings.Index(out, "first"), strings.Index(out, "second")) + require.Less(t, strings.Index(out, "second"), strings.Index(out, "third")) + }) + + t.Run("reverse keeps the source order", func(t *testing.T) { + out := run(t, true) + require.Less(t, strings.Index(out, "third"), strings.Index(out, "second")) + require.Less(t, strings.Index(out, "second"), strings.Index(out, "first")) + }) } From afba8d77ddc210b9cd5a266d72b733565a27b9bf Mon Sep 17 00:00:00 2001 From: Valdemar Pereira Date: Sun, 2 Aug 2026 22:31:52 +0100 Subject: [PATCH 12/20] fix(log): drain buffered entries on follow error; cover filter, to, utc and source paths --- vcr/instance/log/log.go | 35 +++- vcr/instance/log/log_test.go | 317 ++++++++++++++++++++++++++++++++++- 2 files changed, 341 insertions(+), 11 deletions(-) diff --git a/vcr/instance/log/log.go b/vcr/instance/log/log.go index 244924e..b7e484e 100644 --- a/vcr/instance/log/log.go +++ b/vcr/instance/log/log.go @@ -251,7 +251,7 @@ func runHistory(src logs.Source, opts *Options, q logs.Query, filter *logs.Filte page, err := src.History(ctx, q) if err != nil { - return fmt.Errorf("failed to fetch logs: %w", err) + return fmt.Errorf("log history unavailable: %w", err) } // History returns newest-first; print chronologically unless --reverse. @@ -298,23 +298,40 @@ func runFollow(src logs.Source, opts *Options, q logs.Query, filter *logs.Filter errCh := make(chan error, 1) go func() { errCh <- src.Follow(ctx, q, entries) }() + // show applies the shared per-entry handling: assign a replica short id, + // retain the entry in the ring buffer, then print it if it passes the filter. + show := func(e logs.Entry) { + e.ReplicaID = registry.Ensure(e.Hostname).ShortID + buf.Add(e) + if !filter.Match(e) { + return + } + emit(opts, renderer, e) + } + for { select { case <-interrupt: fmt.Fprintf(io.ErrOut, "\n%s stopped\n", c.SuccessIcon()) return nil case err := <-errCh: + // The source has stopped, but entries it already delivered may still + // be sitting in the channel buffer. Render those before returning so + // a late failure does not silently discard successful polls. The + // drain is non-blocking, so an empty channel returns immediately. if err != nil { - return fmt.Errorf("failed to stream logs: %w", err) + err = fmt.Errorf("failed to stream logs: %w", err) } - return nil - case e := <-entries: - e.ReplicaID = registry.Ensure(e.Hostname).ShortID - buf.Add(e) - if !filter.Match(e) { - continue + for { + select { + case e := <-entries: + show(e) + default: + return err + } } - emit(opts, renderer, e) + case e := <-entries: + show(e) } } } diff --git a/vcr/instance/log/log_test.go b/vcr/instance/log/log_test.go index 62df6f7..a27184e 100644 --- a/vcr/instance/log/log_test.go +++ b/vcr/instance/log/log_test.go @@ -4,6 +4,7 @@ import ( "bytes" "context" "errors" + "fmt" "io" "os" "strings" @@ -44,6 +45,20 @@ func Test_buildQueryAndFilter(t *testing.T) { require.Contains(t, err.Error(), "--from") }) + t.Run("to sets To", func(t *testing.T) { + opts := &Options{To: "2026-08-02T11:00:00Z"} + q, _, err := buildQueryAndFilter(opts) + require.NoError(t, err) + require.Equal(t, time.Date(2026, 8, 2, 11, 0, 0, 0, time.UTC), q.To.UTC()) + }) + + t.Run("invalid to is rejected", func(t *testing.T) { + opts := &Options{To: "not-a-time"} + _, _, err := buildQueryAndFilter(opts) + require.Error(t, err) + require.Contains(t, err.Error(), "--to") + }) + t.Run("invalid grep is rejected", func(t *testing.T) { opts := &Options{Grep: "("} _, _, err := buildQueryAndFilter(opts) @@ -74,6 +89,28 @@ func Test_buildQueryAndFilter(t *testing.T) { }) } +func Test_newSource(t *testing.T) { + ios, _, _, _ := iostreams.Test() + f := testutil.DefaultFactoryMock(t, ios, nil, nil, nil, nil, nil, nil) + + for _, name := range []string{"", "auto", "graphql"} { + t.Run("accepts "+name, func(t *testing.T) { + src, err := newSource(&Options{Factory: f, SourceName: name}) + require.NoError(t, err) + require.Equal(t, "graphql", src.Name()) + }) + } + + t.Run("rejects an unknown source and names the accepted values", func(t *testing.T) { + src, err := newSource(&Options{Factory: f, SourceName: "stream"}) + require.Error(t, err) + require.Nil(t, src) + require.Contains(t, err.Error(), `unknown --source "stream"`) + require.Contains(t, err.Error(), "auto") + require.Contains(t, err.Error(), "graphql") + }) +} + func TestLog(t *testing.T) { type mock struct { LogListLogsByInstanceIDTimes int @@ -196,6 +233,28 @@ func TestLog(t *testing.T) { stderr: "! no matching log entries in range\n", }, }, + { + name: "malformed-to-fails-closed", + cli: "--id=abc-123 --to=not-a-time", + mock: mock{ + LogListLogsByInstanceIDTimes: 0, + LogGetInstanceByIDTimes: 0, + }, + want: want{ + errMsg: `failed to validate flags: invalid --to value "not-a-time": expected RFC3339`, + }, + }, + { + name: "unknown-source-is-rejected-and-names-accepted-values", + cli: "--id=abc-123 --source=stream", + mock: mock{ + LogListLogsByInstanceIDTimes: 0, + LogGetInstanceByIDTimes: 0, + }, + want: want{ + errMsg: `failed to select log source: unknown --source "stream": want auto or graphql`, + }, + }, { name: "default-no-follow-get-instance-error", cli: "--id=bad-id", @@ -322,11 +381,13 @@ func TestLog_Follow(t *testing.T) { // fakeFollowSource records the context handed to Follow so a test can assert the // follow loop is not bounded by the global --timeout deadline. It also serves a -// canned History page. +// canned History page and can emit a canned stream of entries. type fakeFollowSource struct { hadDeadline bool followErr error historyPage logs.Page + // emit is delivered on the Follow channel before followErr is returned. + emit []logs.Entry } func (s *fakeFollowSource) Name() string { return "fake" } @@ -336,11 +397,37 @@ func (s *fakeFollowSource) History(_ context.Context, _ logs.Query) (logs.Page, return s.historyPage, nil } -func (s *fakeFollowSource) Follow(ctx context.Context, _ logs.Query, _ chan<- logs.Entry) error { +func (s *fakeFollowSource) Follow(ctx context.Context, _ logs.Query, out chan<- logs.Entry) error { _, s.hadDeadline = ctx.Deadline() + for _, e := range s.emit { + select { + case out <- e: + case <-ctx.Done(): + return nil + } + } return s.followErr } +// runFollowWithTimeout runs runFollow on a goroutine with a hard backstop so a +// regression that stops the loop from returning fails the test instead of +// hanging CI. Reading the output buffer after this returns is safe: the channel +// receive synchronises with every write runFollow made. +func runFollowWithTimeout(t *testing.T, src logs.Source, opts *Options, filter *logs.Filter, renderer *logs.Renderer) error { + t.Helper() + done := make(chan error, 1) + go func() { + done <- runFollow(src, opts, logs.Query{}, filter, renderer, logs.NewBuffer(opts.BufferSize), logs.NewRegistry()) + }() + select { + case err := <-done: + return err + case <-time.After(10 * time.Second): + t.Fatal("runFollow did not return within 10s") + return nil + } +} + // Test_runFollow_isNotBoundedByGlobalTimeout pins defect fix 1: deriving the // follow context from opts.Deadline() used to kill --follow after --timeout. func Test_runFollow_isNotBoundedByGlobalTimeout(t *testing.T) { @@ -404,3 +491,229 @@ func Test_runHistory_ordering(t *testing.T) { require.Less(t, strings.Index(out, "second"), strings.Index(out, "first")) }) } + +// Test_runFollow_rendersBufferedEntriesOnSourceError pins the drain added for +// review finding 1: when the source fails after successful polls, entries it +// already delivered are still in the channel buffer and must be printed rather +// than discarded by the error branch winning the select. +// +// The source emits a burst large enough that it outpaces the render loop, so by +// the time the error lands on errCh the entries channel still holds many +// entries. Without the drain the error branch discards them and the assertion +// below fails. +func Test_runFollow_rendersBufferedEntriesOnSourceError(t *testing.T) { + ios, _, stdout, _ := iostreams.Test() + f := testutil.DefaultFactoryMock(t, ios, nil, nil, nil, nil, nil, nil) + opts := &Options{Factory: f, Follow: true, BufferSize: 10} + + const burst = 128 + base := time.Date(2026, 8, 2, 10, 0, 0, 0, time.UTC) + emit := make([]logs.Entry, 0, burst) + for i := 0; i < burst; i++ { + emit = append(emit, logs.Entry{ + Timestamp: base.Add(time.Duration(i) * time.Millisecond), + Level: "info", + Message: fmt.Sprintf("delivered-%03d", i), + }) + } + src := &fakeFollowSource{followErr: errors.New("transport died"), emit: emit} + + err := runFollowWithTimeout(t, src, opts, &logs.Filter{}, + logs.NewRenderer(ios.ColorScheme(), logs.RenderOptions{})) + + require.Error(t, err) + require.Contains(t, err.Error(), "failed to stream logs: transport died") + + out := stdout.String() + for i := 0; i < burst; i++ { + require.Contains(t, out, fmt.Sprintf("delivered-%03d", i), + "entries already delivered by the source must be drained and rendered before returning the error") + } +} + +// Test_runFollow_rendersBufferedEntriesOnCleanStop is the same drain guarantee on +// the clean (nil error) exit path. +func Test_runFollow_rendersBufferedEntriesOnCleanStop(t *testing.T) { + ios, _, stdout, _ := iostreams.Test() + f := testutil.DefaultFactoryMock(t, ios, nil, nil, nil, nil, nil, nil) + opts := &Options{Factory: f, Follow: true, BufferSize: 10} + + const burst = 128 + base := time.Date(2026, 8, 2, 10, 0, 0, 0, time.UTC) + emit := make([]logs.Entry, 0, burst) + for i := 0; i < burst; i++ { + emit = append(emit, logs.Entry{ + Timestamp: base.Add(time.Duration(i) * time.Millisecond), + Level: "info", + Message: fmt.Sprintf("last-gasp-%03d", i), + }) + } + + err := runFollowWithTimeout(t, &fakeFollowSource{emit: emit}, opts, &logs.Filter{}, + logs.NewRenderer(ios.ColorScheme(), logs.RenderOptions{})) + + require.NoError(t, err) + out := stdout.String() + for i := 0; i < burst; i++ { + require.Contains(t, out, fmt.Sprintf("last-gasp-%03d", i), + "entries already delivered by the source must be drained on a clean stop too") + } +} + +// Test_runFollow_appliesFilter pins review finding 2: follow mode must apply the +// same filter as history mode, so entries below --log-level never reach stdout. +func Test_runFollow_appliesFilter(t *testing.T) { + base := time.Date(2026, 8, 2, 10, 0, 0, 0, time.UTC) + entries := []logs.Entry{ + {Timestamp: base, Level: "info", Message: "chatty-info-line"}, + {Timestamp: base.Add(time.Second), Level: "error", Message: "important-error-line"}, + } + + t.Run("log-level threshold", func(t *testing.T) { + ios, _, stdout, _ := iostreams.Test() + f := testutil.DefaultFactoryMock(t, ios, nil, nil, nil, nil, nil, nil) + opts := &Options{Factory: f, Follow: true, BufferSize: 10, LogLevel: "error"} + + _, filter, err := buildQueryAndFilter(opts) + require.NoError(t, err) + + err = runFollowWithTimeout(t, &fakeFollowSource{emit: entries}, opts, filter, + logs.NewRenderer(ios.ColorScheme(), logs.RenderOptions{})) + require.NoError(t, err) + + out := stdout.String() + require.Contains(t, out, "important-error-line") + require.NotContains(t, out, "chatty-info-line", "--log-level must filter follow-mode entries") + }) + + t.Run("grep pattern", func(t *testing.T) { + ios, _, stdout, _ := iostreams.Test() + f := testutil.DefaultFactoryMock(t, ios, nil, nil, nil, nil, nil, nil) + opts := &Options{Factory: f, Follow: true, BufferSize: 10, Grep: "important"} + + _, filter, err := buildQueryAndFilter(opts) + require.NoError(t, err) + + err = runFollowWithTimeout(t, &fakeFollowSource{emit: entries}, opts, filter, + logs.NewRenderer(ios.ColorScheme(), logs.RenderOptions{})) + require.NoError(t, err) + + out := stdout.String() + require.Contains(t, out, "important-error-line") + require.NotContains(t, out, "chatty-info-line", "--grep must filter follow-mode entries") + }) +} + +// Test_runLog_queriesResolvedInstanceID pins review finding 3: the id handed to +// the datastore's log query must be the resolved instance's ID, not whatever the +// user typed (and not the empty string on the project/instance-name path). +func Test_runLog_queriesResolvedInstanceID(t *testing.T) { + t.Run("id flag uses the resolved id", func(t *testing.T) { + ctrl := gomock.NewController(t) + datastoreMock := mocks.NewMockDatastoreInterface(ctrl) + + // The lookup canonicalises the id, so the queried id differs from --id. + datastoreMock.EXPECT(). + GetInstanceByID(gomock.Any(), "alias-id"). + Times(1). + Return(api.Instance{ID: "resolved-abc-999"}, nil) + + var gotID string + datastoreMock.EXPECT(). + ListLogsByInstanceID(gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any()). + Times(1). + DoAndReturn(func(_ context.Context, id string, _ int, _ time.Time) ([]api.Log, error) { + gotID = id + return []api.Log{{Timestamp: time.Now(), SourceType: "application", Message: "hello"}}, nil + }) + + ios, _, stdout, _ := iostreams.Test() + f := testutil.DefaultFactoryMock(t, ios, nil, nil, datastoreMock, nil, nil, nil) + + cmd := NewCmdInstanceLog(f) + cmd.SetArgs([]string{"--id=alias-id"}) + cmd.SetIn(&bytes.Buffer{}) + cmd.SetOut(io.Discard) + cmd.SetErr(io.Discard) + + _, err := cmd.ExecuteC() + require.NoError(t, err) + require.Equal(t, "resolved-abc-999", gotID, "the log query must use the resolved instance id") + require.Contains(t, stdout.String(), "hello") + }) + + t.Run("project-name and instance-name resolve to an id", func(t *testing.T) { + ctrl := gomock.NewController(t) + datastoreMock := mocks.NewMockDatastoreInterface(ctrl) + + datastoreMock.EXPECT(). + GetInstanceByProjectAndInstanceName(gomock.Any(), "my-app", "dev"). + Times(1). + Return(api.Instance{ID: "resolved-from-names"}, nil) + + var gotID string + datastoreMock.EXPECT(). + ListLogsByInstanceID(gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any()). + Times(1). + DoAndReturn(func(_ context.Context, id string, _ int, _ time.Time) ([]api.Log, error) { + gotID = id + return []api.Log{{Timestamp: time.Now(), SourceType: "application", Message: "named-instance-line"}}, nil + }) + + ios, _, stdout, _ := iostreams.Test() + f := testutil.DefaultFactoryMock(t, ios, nil, nil, datastoreMock, nil, nil, nil) + + cmd := NewCmdInstanceLog(f) + cmd.SetArgs([]string{"--project-name=my-app", "--instance-name=dev"}) + cmd.SetIn(&bytes.Buffer{}) + cmd.SetOut(io.Discard) + cmd.SetErr(io.Discard) + + _, err := cmd.ExecuteC() + require.NoError(t, err) + require.Equal(t, "resolved-from-names", gotID, "the log query must use the id resolved from the names") + require.Contains(t, stdout.String(), "named-instance-line") + }) +} + +// Test_runLog_utcReachesRenderer pins review finding 4b: --utc must be handed to +// the renderer so timestamps print in UTC rather than local time. +func Test_runLog_utcReachesRenderer(t *testing.T) { + // Pin a non-UTC local zone, otherwise the local and UTC renderings of the + // same instant would be identical on a UTC CI machine and the assertion + // below would be vacuous. Not parallel-safe, so this test is not parallel. + origLocal := time.Local + time.Local = time.FixedZone("TEST+09", 9*60*60) + t.Cleanup(func() { time.Local = origLocal }) + + ts := time.Date(2026, 8, 2, 23, 30, 15, 500*int(time.Millisecond), time.UTC) + const wantUTC = "23:30:15.500" // ts rendered in UTC + const wantLocal = "08:30:15.500" // ts rendered in TEST+09 + + ctrl := gomock.NewController(t) + datastoreMock := mocks.NewMockDatastoreInterface(ctrl) + datastoreMock.EXPECT(). + GetInstanceByID(gomock.Any(), "abc-123"). + Times(1). + Return(api.Instance{ID: "abc-123"}, nil) + datastoreMock.EXPECT(). + ListLogsByInstanceID(gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any()). + Times(1). + Return([]api.Log{{Timestamp: ts, SourceType: "application", LogLevel: "info", Message: "utc-line"}}, nil) + + ios, _, stdout, _ := iostreams.Test() + f := testutil.DefaultFactoryMock(t, ios, nil, nil, datastoreMock, nil, nil, nil) + + cmd := NewCmdInstanceLog(f) + cmd.SetArgs([]string{"--id=abc-123", "--utc"}) + cmd.SetIn(&bytes.Buffer{}) + cmd.SetOut(io.Discard) + cmd.SetErr(io.Discard) + + _, err := cmd.ExecuteC() + require.NoError(t, err) + + out := stdout.String() + require.Contains(t, out, wantUTC, "--utc must reach the renderer") + require.NotContains(t, out, wantLocal, "--utc must not render local time") +} From 1eb9cd14fc9fa091e4c05615b7134b19229aa81f Mon Sep 17 00:00:00 2001 From: Valdemar Pereira Date: Sun, 2 Aug 2026 22:48:27 +0100 Subject: [PATCH 13/20] fix(log): drain on interrupt and cover the history error branch Ctrl+C ends nearly every real --follow session, but the interrupt branch returned without draining, discarding up to 256 entries the source had already delivered. Both exit paths now call a shared non-blocking drain closure, so a stop never silently drops successful polls. The runHistory error branch was untested: every TestLog row left the datastore's list-logs error nil, so returning nil there passed the suite and vcr logs could exit 0 with empty output on a backend failure. Add a dedicated test pinning the branch, the wrapper, the underlying cause and the absence of the old wrapper stutter. Also reword the history error to failed to fetch log history to match the file's convention, and route the two remaining direct runFollow calls through the bounded helper so a non-returning regression fails fast. --- vcr/instance/log/log.go | 34 ++++---- vcr/instance/log/log_test.go | 152 ++++++++++++++++++++++++++++++++++- 2 files changed, 168 insertions(+), 18 deletions(-) diff --git a/vcr/instance/log/log.go b/vcr/instance/log/log.go index b7e484e..cb804d8 100644 --- a/vcr/instance/log/log.go +++ b/vcr/instance/log/log.go @@ -251,7 +251,7 @@ func runHistory(src logs.Source, opts *Options, q logs.Query, filter *logs.Filte page, err := src.History(ctx, q) if err != nil { - return fmt.Errorf("log history unavailable: %w", err) + return fmt.Errorf("failed to fetch log history: %w", err) } // History returns newest-first; print chronologically unless --reverse. @@ -309,27 +309,33 @@ func runFollow(src logs.Source, opts *Options, q logs.Query, filter *logs.Filter emit(opts, renderer, e) } + // drain renders entries the source already delivered that are still sitting + // in the channel buffer. Every exit path calls it so a stop — whether from + // Ctrl+C or from a source failure — never silently discards successful + // polls. It is non-blocking: an empty channel returns immediately. + drain := func() { + for { + select { + case e := <-entries: + show(e) + default: + return + } + } + } + for { select { case <-interrupt: + drain() fmt.Fprintf(io.ErrOut, "\n%s stopped\n", c.SuccessIcon()) return nil case err := <-errCh: - // The source has stopped, but entries it already delivered may still - // be sitting in the channel buffer. Render those before returning so - // a late failure does not silently discard successful polls. The - // drain is non-blocking, so an empty channel returns immediately. + drain() if err != nil { - err = fmt.Errorf("failed to stream logs: %w", err) - } - for { - select { - case e := <-entries: - show(e) - default: - return err - } + return fmt.Errorf("failed to stream logs: %w", err) } + return nil case e := <-entries: show(e) } diff --git a/vcr/instance/log/log_test.go b/vcr/instance/log/log_test.go index a27184e..6424057 100644 --- a/vcr/instance/log/log_test.go +++ b/vcr/instance/log/log_test.go @@ -7,7 +7,9 @@ import ( "fmt" "io" "os" + "os/signal" "strings" + "sync" "testing" "time" @@ -436,8 +438,8 @@ func Test_runFollow_isNotBoundedByGlobalTimeout(t *testing.T) { opts := &Options{Factory: f, Follow: true, BufferSize: 10} src := &fakeFollowSource{} - err := runFollow(src, opts, logs.Query{}, &logs.Filter{}, - logs.NewRenderer(ios.ColorScheme(), logs.RenderOptions{}), logs.NewBuffer(10), logs.NewRegistry()) + err := runFollowWithTimeout(t, src, opts, &logs.Filter{}, + logs.NewRenderer(ios.ColorScheme(), logs.RenderOptions{})) require.NoError(t, err) require.False(t, src.hadDeadline, "follow context must not carry the global --timeout deadline") @@ -449,8 +451,8 @@ func Test_runFollow_wrapsSourceError(t *testing.T) { opts := &Options{Factory: f, Follow: true, BufferSize: 10} src := &fakeFollowSource{followErr: errors.New("transport died")} - err := runFollow(src, opts, logs.Query{}, &logs.Filter{}, - logs.NewRenderer(ios.ColorScheme(), logs.RenderOptions{}), logs.NewBuffer(10), logs.NewRegistry()) + err := runFollowWithTimeout(t, src, opts, &logs.Filter{}, + logs.NewRenderer(ios.ColorScheme(), logs.RenderOptions{})) require.Error(t, err) require.Contains(t, err.Error(), "failed to stream logs: transport died") @@ -560,6 +562,148 @@ func Test_runFollow_rendersBufferedEntriesOnCleanStop(t *testing.T) { } } +// gateWriter holds the render loop still until release is closed, then writes +// straight through. It lets the interrupt-drain test guarantee that the source +// has finished delivering and that the interrupt is already pending before the +// loop renders anything else, so the assertion does not depend on how fast the +// render loop happens to run. Only runFollow writes through it, so no locking +// is needed; runFollowWithTimeout's channel receive synchronises the read. +type gateWriter struct { + release <-chan struct{} + opened sync.Once + w io.Writer +} + +// Fd satisfies the unexported writer interface iostreams.IOStreams.Out requires. +func (g *gateWriter) Fd() uintptr { return 1 } + +func (g *gateWriter) Write(p []byte) (int, error) { + g.opened.Do(func() { <-g.release }) + return g.w.Write(p) +} + +// interruptingSource delivers a burst of entries and then interrupts the +// process, which is how a real --follow session almost always ends. It closes +// release only once the interrupt has been observed by a second handler, which +// proves the follow loop's own interrupt channel has been served too, and then +// parks on ctx so it never races the loop to errCh. +type interruptingSource struct { + emit []logs.Entry + release chan struct{} + pending <-chan os.Signal +} + +func (s *interruptingSource) Name() string { return "interrupting" } +func (s *interruptingSource) Caps() logs.Caps { return logs.Caps{} } + +func (s *interruptingSource) History(_ context.Context, _ logs.Query) (logs.Page, error) { + return logs.Page{}, nil +} + +func (s *interruptingSource) Follow(ctx context.Context, _ logs.Query, out chan<- logs.Entry) error { + for _, e := range s.emit { + select { + case out <- e: + case <-ctx.Done(): + return nil + } + } + p, err := os.FindProcess(os.Getpid()) + if err != nil { + return err + } + if err := p.Signal(os.Interrupt); err != nil { + return err + } + <-s.pending + close(s.release) + <-ctx.Done() + return nil +} + +// Test_runFollow_rendersBufferedEntriesOnInterrupt pins the drain on the +// interrupt branch: Ctrl+C ends nearly every real --follow session, and the +// branch used to return without draining, discarding up to 256 entries the +// source had already delivered. +// +// The source fills the channel buffer and holds the render loop on its first +// write until the interrupt is pending, so when the loop resumes both the +// interrupt and the remaining entries are ready. Without the drain the +// interrupt branch wins the select after a handful of entries and the rest are +// lost; with it, every entry is rendered. +func Test_runFollow_rendersBufferedEntriesOnInterrupt(t *testing.T) { + ios, _, stdout, _ := iostreams.Test() + + release := make(chan struct{}) + ios.Out = &gateWriter{release: release, w: stdout} + + pending := make(chan os.Signal, 1) + signal.Notify(pending, os.Interrupt) + t.Cleanup(func() { signal.Stop(pending) }) + + f := testutil.DefaultFactoryMock(t, ios, nil, nil, nil, nil, nil, nil) + opts := &Options{Factory: f, Follow: true, BufferSize: 10} + + const burst = 128 + base := time.Date(2026, 8, 2, 10, 0, 0, 0, time.UTC) + emit := make([]logs.Entry, 0, burst) + for i := 0; i < burst; i++ { + emit = append(emit, logs.Entry{ + Timestamp: base.Add(time.Duration(i) * time.Millisecond), + Level: "info", + Message: fmt.Sprintf("interrupted-%03d", i), + }) + } + + src := &interruptingSource{emit: emit, release: release, pending: pending} + err := runFollowWithTimeout(t, src, opts, &logs.Filter{}, + logs.NewRenderer(ios.ColorScheme(), logs.RenderOptions{})) + + require.NoError(t, err, "an interrupt is a clean stop") + out := stdout.String() + for i := 0; i < burst; i++ { + require.Contains(t, out, fmt.Sprintf("interrupted-%03d", i), + "entries already delivered by the source must be drained and rendered before Ctrl+C returns") + } +} + +// Test_runLog_historyErrorIsReportedOnce pins the runHistory error branch: a +// backend failure must surface as a non-zero exit rather than an empty run that +// looks successful. It also pins that the command layer names the failing step +// without repeating the source layer's own "failed to list logs" phrasing. +func Test_runLog_historyErrorIsReportedOnce(t *testing.T) { + ctrl := gomock.NewController(t) + datastoreMock := mocks.NewMockDatastoreInterface(ctrl) + + datastoreMock.EXPECT(). + GetInstanceByID(gomock.Any(), "abc-123"). + Times(1). + Return(api.Instance{ID: "abc-123"}, nil) + datastoreMock.EXPECT(). + ListLogsByInstanceID(gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any()). + Times(1). + Return(nil, errors.New("datastore unreachable")) + + ios, _, stdout, _ := iostreams.Test() + f := testutil.DefaultFactoryMock(t, ios, nil, nil, datastoreMock, nil, nil, nil) + + cmd := NewCmdInstanceLog(f) + cmd.SetArgs([]string{"--id=abc-123"}) + cmd.SetIn(&bytes.Buffer{}) + cmd.SetOut(io.Discard) + cmd.SetErr(io.Discard) + + _, err := cmd.ExecuteC() + require.Error(t, err, "a backend failure must not exit 0 with empty output") + require.Contains(t, err.Error(), "failed to fetch log history:", + "the command layer must name the step that failed") + require.Contains(t, err.Error(), "datastore unreachable", + "the underlying cause must survive wrapping") + require.Equal(t, 1, strings.Count(err.Error(), "failed to list logs"), + "the command wrapper must not repeat the source layer's phrasing") + require.Empty(t, stdout.String(), "nothing should be printed when the fetch fails") +} + // Test_runFollow_appliesFilter pins review finding 2: follow mode must apply the // same filter as history mode, so entries below --log-level never reach stdout. func Test_runFollow_appliesFilter(t *testing.T) { From 963bf2dc7de84dc0eb2111ea1f3a2a0e0272766a Mon Sep 17 00:00:00 2001 From: Valdemar Pereira Date: Sun, 2 Aug 2026 22:58:13 +0100 Subject: [PATCH 14/20] feat(log): add top-level 'vcr logs' alias --- vcr/instance/log/log_test.go | 11 +++++++++++ vcr/root/root.go | 2 ++ 2 files changed, 13 insertions(+) diff --git a/vcr/instance/log/log_test.go b/vcr/instance/log/log_test.go index 6424057..b8b36d6 100644 --- a/vcr/instance/log/log_test.go +++ b/vcr/instance/log/log_test.go @@ -861,3 +861,14 @@ func Test_runLog_utcReachesRenderer(t *testing.T) { require.Contains(t, out, wantUTC, "--utc must reach the renderer") require.NotContains(t, out, wantLocal, "--utc must not render local time") } + +func TestNewCmdLogs_TopLevelAlias(t *testing.T) { + ios, _, _, _ := iostreams.Test() + f := testutil.DefaultFactoryMock(t, ios, nil, nil, nil, nil, nil, nil) + + cmd := NewCmdLogs(f) + require.Equal(t, "logs", cmd.Use) + require.Empty(t, cmd.Aliases) + require.NotNil(t, cmd.Flags().Lookup("follow")) + require.NotNil(t, cmd.Flags().Lookup("since")) +} diff --git a/vcr/root/root.go b/vcr/root/root.go index 4289eb9..140a34d 100644 --- a/vcr/root/root.go +++ b/vcr/root/root.go @@ -19,6 +19,7 @@ import ( deployCmd "vonage-cloud-runtime-cli/vcr/deploy" initCmd "vonage-cloud-runtime-cli/vcr/init" instanceCmd "vonage-cloud-runtime-cli/vcr/instance" + logCmd "vonage-cloud-runtime-cli/vcr/instance/log" secretCmd "vonage-cloud-runtime-cli/vcr/secret" upgradeCmd "vonage-cloud-runtime-cli/vcr/upgrade" ) @@ -180,6 +181,7 @@ func NewCmdRoot(f cmdutil.Factory, version, buildDate, commit string, updateStre cmd.AddCommand(debugCmd.NewCmdDebug(f)) cmd.AddCommand(deployCmd.NewCmdDeploy(f)) cmd.AddCommand(instanceCmd.NewCmdInstance(f)) + cmd.AddCommand(logCmd.NewCmdLogs(f)) cmd.AddCommand(secretCmd.NewCmdSecret(f)) cmd.AddCommand(upgradeCmd.NewCmdUpgrade(f, version)) return cmd From ac4d288f429014670d68ad19c446a95ad6d7519f Mon Sep 17 00:00:00 2001 From: Valdemar Pereira Date: Sun, 2 Aug 2026 23:05:52 +0100 Subject: [PATCH 15/20] test(root): pin the top-level logs command registration The 'vcr logs' shortcut had no coverage of the root wiring: the existing guard test builds the command inside the log package, so deleting the cmd.AddCommand(logCmd.NewCmdLogs(f)) line left the suite green. - add a root-package test asserting a top-level command with Use == "logs" is present in NewCmdRoot(...).Commands(); asserting on Use also catches swapping in NewCmdInstanceLog, whose Use is "log" - document that root's --version must stay a LOCAL flag: 'vcr logs' uses -v for --exclude, so promoting it to PersistentFlags would panic in pflag - assert --grep in the log package's alias guard test --- vcr/instance/log/log_test.go | 1 + vcr/root/root.go | 5 +++++ vcr/root/root_test.go | 21 +++++++++++++++++++++ 3 files changed, 27 insertions(+) diff --git a/vcr/instance/log/log_test.go b/vcr/instance/log/log_test.go index b8b36d6..f88839f 100644 --- a/vcr/instance/log/log_test.go +++ b/vcr/instance/log/log_test.go @@ -871,4 +871,5 @@ func TestNewCmdLogs_TopLevelAlias(t *testing.T) { require.Empty(t, cmd.Aliases) require.NotNil(t, cmd.Flags().Lookup("follow")) require.NotNil(t, cmd.Flags().Lookup("since")) + require.NotNil(t, cmd.Flags().Lookup("grep")) } diff --git a/vcr/root/root.go b/vcr/root/root.go index 140a34d..047b7ae 100644 --- a/vcr/root/root.go +++ b/vcr/root/root.go @@ -166,6 +166,11 @@ func NewCmdRoot(f cmdutil.Factory, version, buildDate, commit string, updateStre }) cmd.SetFlagErrorFunc(rootFlagErrorFunc) + // Keep --version a LOCAL flag. The top-level `vcr logs` command uses -v as the + // shorthand for --exclude, and cobra merges only a parent's persistent flags + // into a child's flagset. Promoting this to PersistentFlags would make pflag's + // AddFlag find shorthand "v" already taken and panic on every `vcr logs` run + // (the name-based Lookup guard does not help: the flag names differ). cmd.Flags().BoolP("version", "v", false, "Show VCR CLI version") cmd.PersistentFlags().Bool("help", false, "Show help for command") cmd.PersistentFlags().StringVarP(&opts.ConfigFilePath, "config-file", "", config.DefaultCLIConfigPath[0], "Path to config file (default is $HOME/.vcr-cli)") diff --git a/vcr/root/root_test.go b/vcr/root/root_test.go index 81253ad..37d45c4 100644 --- a/vcr/root/root_test.go +++ b/vcr/root/root_test.go @@ -84,3 +84,24 @@ func TestCheckForUpdate(t *testing.T) { }) } } + +// TestNewCmdRoot_registersTopLevelLogs pins the `vcr logs` shortcut to the root +// command's wiring. Asserting on Use (not just "a command was added") means +// registering NewCmdInstanceLog, whose Use is "log", fails here too. +func TestNewCmdRoot_registersTopLevelLogs(t *testing.T) { + ios, _, _, _ := iostreams.Test() + f := testutil.DefaultFactoryMock(t, ios, nil, nil, nil, nil, nil, nil) + + updateStream := make(chan string, 1) + cmd := NewCmdRoot(f, "0.0.1", "2026-08-02", "abcdef0", updateStream) + + var uses []string + found := false + for _, sub := range cmd.Commands() { + uses = append(uses, sub.Use) + if sub.Use == "logs" { + found = true + } + } + require.True(t, found, `root must register a top-level command with Use == "logs"; got %v`, uses) +} From 022eb527fca74bc7e2df70ffde9c5113ca694046 Mon Sep 17 00:00:00 2001 From: Valdemar Pereira Date: Sun, 2 Aug 2026 23:11:45 +0100 Subject: [PATCH 16/20] fix(log): show each registration's own invocation in its examples Both 'vcr logs' and 'vcr instance log' are built by newLogCmd and shared a single hardcoded example block, so 'vcr instance log --help' instructed users to run 'vcr logs ...' - a different command. Parameterise the examples on the fully-qualified invocation. --- vcr/instance/log/log.go | 23 +++++++++++++---------- vcr/instance/log/log_test.go | 21 +++++++++++++++++++++ 2 files changed, 34 insertions(+), 10 deletions(-) diff --git a/vcr/instance/log/log.go b/vcr/instance/log/log.go index cb804d8..d787ca9 100644 --- a/vcr/instance/log/log.go +++ b/vcr/instance/log/log.go @@ -57,15 +57,18 @@ type Options struct { } func NewCmdInstanceLog(f cmdutil.Factory) *cobra.Command { - return newLogCmd(f, "log", []string{"logs"}) + return newLogCmd(f, "log", []string{"logs"}, "vcr instance log") } // NewCmdLogs returns the same command registered at the top level as "vcr logs". func NewCmdLogs(f cmdutil.Factory) *cobra.Command { - return newLogCmd(f, "logs", nil) + return newLogCmd(f, "logs", nil, "vcr logs") } -func newLogCmd(f cmdutil.Factory, use string, aliases []string) *cobra.Command { +// newLogCmd builds the log command. invocation is the fully-qualified way a user +// types this command ("vcr logs" or "vcr instance log"); it is substituted into the +// examples so each registration shows examples that actually work as written. +func newLogCmd(f cmdutil.Factory, use string, aliases []string, invocation string) *cobra.Command { opts := Options{Factory: f} cmd := &cobra.Command{ @@ -100,22 +103,22 @@ func newLogCmd(f cmdutil.Factory, use string, aliases []string) *cobra.Command { --json prints one JSON object per line for scripting. `), Args: cobra.MaximumNArgs(0), - Example: heredoc.Doc(` + Example: fmt.Sprintf(heredoc.Doc(` # Print recent logs and exit - $ vcr logs --project-name my-app --instance-name dev + $ %[1]s --project-name my-app --instance-name dev # Follow new logs (Ctrl+C to stop) - $ vcr logs -p my-app -n dev --follow + $ %[1]s -p my-app -n dev --follow # The last 15 minutes, errors only - $ vcr logs -p my-app -n dev --since 15m --log-level error + $ %[1]s -p my-app -n dev --since 15m --log-level error # An explicit window - $ vcr logs -i 12345678-1234-1234-1234-123456789abc --from 2026-08-02T10:00:00Z --to 2026-08-02T11:00:00Z + $ %[1]s -i 12345678-1234-1234-1234-123456789abc --from 2026-08-02T10:00:00Z --to 2026-08-02T11:00:00Z # Only payment failures, excluding health checks, as JSON - $ vcr logs -p my-app -n dev --grep 'pay.*502' --exclude '/health' --json - `), + $ %[1]s -p my-app -n dev --grep 'pay.*502' --exclude '/health' --json + `), invocation), RunE: func(_ *cobra.Command, _ []string) error { return runLog(&opts) }, diff --git a/vcr/instance/log/log_test.go b/vcr/instance/log/log_test.go index f88839f..b7e069d 100644 --- a/vcr/instance/log/log_test.go +++ b/vcr/instance/log/log_test.go @@ -873,3 +873,24 @@ func TestNewCmdLogs_TopLevelAlias(t *testing.T) { require.NotNil(t, cmd.Flags().Lookup("since")) require.NotNil(t, cmd.Flags().Lookup("grep")) } + +// Both registrations share one help text, so the examples must be rewritten per +// registration. Otherwise `vcr instance log --help` tells the user to type +// `vcr logs ...`, which is a different command. +func TestLogCmd_ExamplesMatchTheirOwnInvocation(t *testing.T) { + ios, _, _, _ := iostreams.Test() + f := testutil.DefaultFactoryMock(t, ios, nil, nil, nil, nil, nil, nil) + + topLevel := NewCmdLogs(f) + require.Contains(t, topLevel.Example, "$ vcr logs ") + require.NotContains(t, topLevel.Example, "vcr instance log") + + nested := NewCmdInstanceLog(f) + require.Contains(t, nested.Example, "$ vcr instance log ") + require.NotContains(t, nested.Example, "$ vcr logs ", + "vcr instance log examples must not tell the user to run vcr logs") + + // No unsubstituted verbs leaked into either help text. + require.NotContains(t, topLevel.Example, "%!") + require.NotContains(t, nested.Example, "%!") +} From a891212b04398f78d73389b9ad4d1f46999aed80 Mon Sep 17 00:00:00 2001 From: Valdemar Pereira Date: Sun, 2 Aug 2026 23:12:04 +0100 Subject: [PATCH 17/20] docs: regenerate CLI reference for the new log flags and vcr logs alias Covers only the log-related pages. The rest of docs/ has drifted from the command tree independently of this branch and is left for a separate cleanup. --- docs/vcr.md | 73 ++++++++++++++++++++++++------ docs/vcr_instance_log.md | 76 +++++++++++++++++++++---------- docs/vcr_logs.md | 98 ++++++++++++++++++++++++++++++++++++++++ 3 files changed, 211 insertions(+), 36 deletions(-) create mode 100644 docs/vcr_logs.md diff --git a/docs/vcr.md b/docs/vcr.md index 9ccf35a..dfafed1 100644 --- a/docs/vcr.md +++ b/docs/vcr.md @@ -5,17 +5,64 @@ Streamline your Vonage Cloud Runtime development and management tasks with VCR ### Synopsis VCR CLI is a powerful command-line interface designed to streamline -and simplify the development and management of applications on +and simplify the development and management of applications on the Vonage Cloud Runtime platform. +Vonage Cloud Runtime (VCR) enables you to build, deploy, and run serverless +applications that integrate with Vonage communication APIs including Voice, +Messages, and RTC (Real-Time Communication). + +GETTING STARTED + 1. Configure the CLI with your Vonage API credentials: + $ vcr configure + + 2. Initialize a new project from a template: + $ vcr init my-project + + 3. Deploy your application: + $ vcr deploy + +CORE WORKFLOW + • vcr configure - Set up your Vonage API credentials and region + • vcr app - Create and manage Vonage applications + • vcr init - Initialize a project from a template + • vcr deploy - Deploy your application to VCR + • vcr debug - Run your application locally in debug mode + • vcr instance - Manage deployed instances (logs, removal) + • vcr secret - Manage secrets for your applications + • vcr upgrade - Update the VCR CLI to the latest version + ### Examples ``` -$ vcr app create -n my-app +# Configure the CLI with your Vonage credentials +$ vcr configure + +# Create a new Vonage application +$ vcr app create --name my-app + +# List all your Vonage applications $ vcr app list + +# Initialize a new project in the current directory $ vcr init +# Initialize a new project in a specific directory +$ vcr init my-project + +# Deploy your application to VCR +$ vcr deploy + +# Run your application locally in debug mode +$ vcr debug + +# View logs for a deployed instance +$ vcr instance log --project-name my-project --instance-name dev + +# Create a secret for your application +$ vcr secret create --name MY_API_KEY --value "secret-value" + ``` ### Options @@ -33,14 +80,14 @@ $ vcr init ### SEE ALSO -* [vcr app](vcr_app.md) - Use app commands to manage Vonage applications -* [vcr configure](vcr_configure.md) - Configure VCR CLI -* [vcr debug](vcr_debug.md) - Run the application code locally in debug mode. -* [vcr deploy](vcr_deploy.md) - Deploy a VCR application -* [vcr init](vcr_init.md) - Initialise a new code template -* [vcr instance](vcr_instance.md) - Used for instance management -* [vcr mongo](vcr_mongo.md) - Used for managing MongoDB databases -* [vcr secret](vcr_secret.md) - Manage VCR secrets -* [vcr upgrade](vcr_upgrade.md) - Show and update VCR CLI version - -###### Auto generated by spf13/cobra on 26-Nov-2024 +* [vcr app](vcr_app.md) - Manage Vonage applications for VCR deployments +* [vcr configure](vcr_configure.md) - Configure VCR CLI with your Vonage API credentials +* [vcr debug](vcr_debug.md) - Run your application locally in debug mode with live VCR integration +* [vcr deploy](vcr_deploy.md) - Deploy your application to Vonage Cloud Runtime +* [vcr init](vcr_init.md) - Initialize a new VCR project from a template +* [vcr instance](vcr_instance.md) - Manage deployed VCR instances +* [vcr logs](vcr_logs.md) - Fetch logs from a deployed VCR instance +* [vcr secret](vcr_secret.md) - Manage secrets for VCR applications +* [vcr upgrade](vcr_upgrade.md) - Check for and install VCR CLI updates + +###### Auto generated by spf13/cobra on 2-Aug-2026 diff --git a/docs/vcr_instance_log.md b/docs/vcr_instance_log.md index e7ccd80..30e6901 100644 --- a/docs/vcr_instance_log.md +++ b/docs/vcr_instance_log.md @@ -1,52 +1,82 @@ ## vcr instance log +Fetch logs from a deployed VCR instance + +### Synopsis + Fetch logs from a deployed VCR instance. -By default, the command retrieves the last N log entries (controlled by `--history`) and exits. -Use the `--follow` (`-f`) flag to continuously stream new log entries until you press Ctrl+C. +By default the command prints recent log entries and exits. Use --follow (-f) +to keep streaming new entries until you press Ctrl+C. + +IDENTIFYING THE INSTANCE + • --id: the instance UUID + • --project-name + --instance-name: the combination from your manifest + +SELECTING A TIME RANGE + • --since 15m|2h start from a relative point in the past + • --from/--to RFC3339 an explicit window + • --history N limit the initial backfill (default 300) + --since and --from are mutually exclusive. --history composes with a + window: the last N entries within it. + +FILTERING + • --log-level minimum severity: trace, debug, info, warn, error, fatal + • --source-type application | provider + • --grep show only messages matching a Go RE2 regex + • --exclude hide messages matching a Go RE2 regex + Use (?i) inside a pattern for case-insensitive matching. + +OUTPUT + Each line is: HH:MM:SS.mmm level message + --json prints one JSON object per line for scripting. + ``` -vcr instance log --project-name --instance-name [flags] +vcr instance log [flags] ``` ### Examples ``` -# Print the last logs by instance id (default, no follow): -$ vcr instance log --id - -# Print the last logs by project and instance name: -$ vcr instance log --project-name --instance-name - -# Continuously stream new logs (follow mode): -$ vcr instance log --project-name --instance-name --follow +# Print recent logs and exit +$ vcr instance log --project-name my-app --instance-name dev -# Follow logs using the short flag: -$ vcr instance log -p -n -f +# Follow new logs (Ctrl+C to stop) +$ vcr instance log -p my-app -n dev --follow -# Print the last 500 log entries and exit: -$ vcr instance log --id --history 500 +# The last 15 minutes, errors only +$ vcr instance log -p my-app -n dev --since 15m --log-level error -# Filter to show only errors and above: -$ vcr instance log -p -n --log-level error +# An explicit window +$ vcr instance log -i 12345678-1234-1234-1234-123456789abc --from 2026-08-02T10:00:00Z --to 2026-08-02T11:00:00Z -# Show only application logs (exclude provider logs): -$ vcr instance log -p -n --source-type application +# Only payment failures, excluding health checks, as JSON +$ vcr instance log -p my-app -n dev --grep 'pay.*502' --exclude '/health' --json -# Combine filters with follow: -$ vcr instance log -p -n -l warn -s application -f ``` ### Options ``` + --buffer int Maximum log entries retained in memory (default 5000) + -v, --exclude string Hide messages matching this RE2 regex -f, --follow Continuously stream new log entries (press Ctrl+C to stop) + --from string Window start (RFC3339) + -g, --grep string Show only messages matching this RE2 regex --history int Number of historical log entries to fetch initially (default 300) -i, --id string Instance UUID (alternative to project-name + instance-name) -n, --instance-name string Instance name (requires --project-name) + --json Print one JSON object per line -l, --log-level string Minimum log level: trace, debug, info, warn, error, fatal -p, --project-name string Project name (requires --instance-name) + --replica string Comma-separated replica ids or hostnames (requires a replica-capable source) + --reverse Reverse the default ordering for the current mode + --since duration Start from this long ago (e.g. 15m, 2h) + --source string Log source: auto, graphql (default "auto") -s, --source-type string Filter by source: application, provider + --to string Window end (RFC3339) + --utc Print timestamps in UTC ``` ### Options inherited from parent commands @@ -63,6 +93,6 @@ $ vcr instance log -p -n -l warn -s application - ### SEE ALSO -* [vcr instance](vcr_instance.md) - Used for instance management +* [vcr instance](vcr_instance.md) - Manage deployed VCR instances -###### Auto generated by spf13/cobra on 13-Apr-2026 +###### Auto generated by spf13/cobra on 2-Aug-2026 diff --git a/docs/vcr_logs.md b/docs/vcr_logs.md new file mode 100644 index 0000000..648e0b0 --- /dev/null +++ b/docs/vcr_logs.md @@ -0,0 +1,98 @@ +## vcr logs + +Fetch logs from a deployed VCR instance + +### Synopsis + +Fetch logs from a deployed VCR instance. + +By default the command prints recent log entries and exits. Use --follow (-f) +to keep streaming new entries until you press Ctrl+C. + +IDENTIFYING THE INSTANCE + • --id: the instance UUID + • --project-name + --instance-name: the combination from your manifest + +SELECTING A TIME RANGE + • --since 15m|2h start from a relative point in the past + • --from/--to RFC3339 an explicit window + • --history N limit the initial backfill (default 300) + --since and --from are mutually exclusive. --history composes with a + window: the last N entries within it. + +FILTERING + • --log-level minimum severity: trace, debug, info, warn, error, fatal + • --source-type application | provider + • --grep show only messages matching a Go RE2 regex + • --exclude hide messages matching a Go RE2 regex + Use (?i) inside a pattern for case-insensitive matching. + +OUTPUT + Each line is: HH:MM:SS.mmm level message + --json prints one JSON object per line for scripting. + + +``` +vcr logs [flags] +``` + +### Examples + +``` +# Print recent logs and exit +$ vcr logs --project-name my-app --instance-name dev + +# Follow new logs (Ctrl+C to stop) +$ vcr logs -p my-app -n dev --follow + +# The last 15 minutes, errors only +$ vcr logs -p my-app -n dev --since 15m --log-level error + +# An explicit window +$ vcr logs -i 12345678-1234-1234-1234-123456789abc --from 2026-08-02T10:00:00Z --to 2026-08-02T11:00:00Z + +# Only payment failures, excluding health checks, as JSON +$ vcr logs -p my-app -n dev --grep 'pay.*502' --exclude '/health' --json + +``` + +### Options + +``` + --buffer int Maximum log entries retained in memory (default 5000) + -v, --exclude string Hide messages matching this RE2 regex + -f, --follow Continuously stream new log entries (press Ctrl+C to stop) + --from string Window start (RFC3339) + -g, --grep string Show only messages matching this RE2 regex + --history int Number of historical log entries to fetch initially (default 300) + -i, --id string Instance UUID (alternative to project-name + instance-name) + -n, --instance-name string Instance name (requires --project-name) + --json Print one JSON object per line + -l, --log-level string Minimum log level: trace, debug, info, warn, error, fatal + -p, --project-name string Project name (requires --instance-name) + --replica string Comma-separated replica ids or hostnames (requires a replica-capable source) + --reverse Reverse the default ordering for the current mode + --since duration Start from this long ago (e.g. 15m, 2h) + --source string Log source: auto, graphql (default "auto") + -s, --source-type string Filter by source: application, provider + --to string Window end (RFC3339) + --utc Print timestamps in UTC +``` + +### Options inherited from parent commands + +``` + --api-key string Vonage API key + --api-secret string Vonage API secret + --config-file string Path to config file (default is $HOME/.vcr-cli) (default "~/.vcr-cli") + --graphql-endpoint string Graphql endpoint used to fetch metadata + --help Show help for command + --region string Vonage platform region + -t, --timeout duration Timeout for requests to Vonage platform (default 10m0s) +``` + +### SEE ALSO + +* [vcr](vcr.md) - Streamline your Vonage Cloud Runtime development and management tasks with VCR + +###### Auto generated by spf13/cobra on 2-Aug-2026 From 7d1014e7dca27e62272ef8710b1826fdb5b62755 Mon Sep 17 00:00:00 2001 From: Valdemar Pereira Date: Sun, 2 Aug 2026 23:47:34 +0100 Subject: [PATCH 18/20] fix(logs): survive transient poll failures and stop misreporting --to Remediates the two blockers and six should-fix findings from the final whole-branch review of feat/logs-streaming. --follow no longer dies on a transient fetch error. GraphQLSource.Follow absorbs a failed poll, hands it to an injected WithFollowErrorHandler callback and retries on the next tick; only MaxFollowPollFailures consecutive failures return an error. The command installs a handler that prints the warning icon to ErrOut, restoring the pre-branch behaviour the design spec specifies. Resilience lives in the source because the spec gives Follow ownership of its own reconnect behaviour, and because nothing polls once Follow has returned. --to no longer claims a window is empty when it was never reached. The backing query can only bound From, ordered newest-first, so a full page can be discarded in its entirety by the client-side To filter. Page gains WindowTruncated for exactly that case and runHistory replaces the misleading "no matching log entries in range" with an actionable warning naming --history and --from. The proper timestamp: {_lt:} query stays deferred. Also: - print a muted "==> YYYY-MM-DD" marker whenever the calendar date changes, in both modes, human format only, honouring --utc - make JSONLine always emit UTC RFC3339 so machine-readable output does not vary with the host timezone - name --grep/--exclude in pattern errors instead of Filter's internal "include pattern" wording - drop the source's "failed to list logs" prefix so the user sees one "failed to ..." rather than two - reject non-positive --history and --buffer instead of silently substituting 200 and 5000 - cancel the source before draining on interrupt, so a second Ctrl+C is not swallowed while the drain renders entries a stopped producer never sent - return a copy from logs.LevelNames() --- docs/vcr_instance_log.md | 6 +- docs/vcr_logs.md | 6 +- pkg/logs/filter.go | 10 +- pkg/logs/filter_test.go | 14 ++ pkg/logs/graphql_source.go | 95 ++++++-- pkg/logs/graphql_source_test.go | 208 +++++++++++++++- pkg/logs/render.go | 59 +++-- pkg/logs/render_test.go | 76 +++++- pkg/logs/source.go | 5 + vcr/instance/log/log.go | 68 +++++- vcr/instance/log/log_test.go | 419 +++++++++++++++++++++++++++++++- 11 files changed, 895 insertions(+), 71 deletions(-) diff --git a/docs/vcr_instance_log.md b/docs/vcr_instance_log.md index 30e6901..5536109 100644 --- a/docs/vcr_instance_log.md +++ b/docs/vcr_instance_log.md @@ -28,8 +28,10 @@ FILTERING Use (?i) inside a pattern for case-insensitive matching. OUTPUT - Each line is: HH:MM:SS.mmm level message - --json prints one JSON object per line for scripting. + Each line is: HH:MM:SS.mmm level message, preceded by a + "==> YYYY-MM-DD" marker whenever the calendar date changes. + --json prints one JSON object per line for scripting, always with + UTC timestamps so output does not vary by host timezone. ``` diff --git a/docs/vcr_logs.md b/docs/vcr_logs.md index 648e0b0..dfab185 100644 --- a/docs/vcr_logs.md +++ b/docs/vcr_logs.md @@ -28,8 +28,10 @@ FILTERING Use (?i) inside a pattern for case-insensitive matching. OUTPUT - Each line is: HH:MM:SS.mmm level message - --json prints one JSON object per line for scripting. + Each line is: HH:MM:SS.mmm level message, preceded by a + "==> YYYY-MM-DD" marker whenever the calendar date changes. + --json prints one JSON object per line for scripting, always with + UTC timestamps so output does not vary by host timezone. ``` diff --git a/pkg/logs/filter.go b/pkg/logs/filter.go index 92e63bc..b5310ef 100644 --- a/pkg/logs/filter.go +++ b/pkg/logs/filter.go @@ -147,5 +147,11 @@ func NextLevel(l Level) Level { return l + 1 } -// LevelNames returns the ladder in order, for help text. -func LevelNames() []string { return levelOrder } +// LevelNames returns a copy of the ladder in order, for help text. It copies so +// a caller cannot reorder or overwrite the shared package slice for everyone +// else in the process. +func LevelNames() []string { + names := make([]string, len(levelOrder)) + copy(names, levelOrder) + return names +} diff --git a/pkg/logs/filter_test.go b/pkg/logs/filter_test.go index 9a78a84..5f60766 100644 --- a/pkg/logs/filter_test.go +++ b/pkg/logs/filter_test.go @@ -60,3 +60,17 @@ func TestFilterSummary(t *testing.T) { require.Contains(t, f.Summary(), "level>=error") require.Contains(t, f.Summary(), "/boom/") } + +// TestLevelNames_ReturnsACopy pins review finding 17: LevelNames used to hand +// out the package-level slice, so any caller could reorder the ladder for every +// other caller in the process. +func TestLevelNames_ReturnsACopy(t *testing.T) { + want := []string{"trace", "debug", "info", "warn", "error", "fatal"} + got := LevelNames() + require.Equal(t, want, got) + + got[0] = "mutated" + require.Equal(t, want, LevelNames(), "mutating the result must not corrupt the package ladder") + + require.NotSame(t, &got[0], &LevelNames()[0], "each call must return a distinct backing array") +} diff --git a/pkg/logs/graphql_source.go b/pkg/logs/graphql_source.go index 895c67e..cec7cc8 100644 --- a/pkg/logs/graphql_source.go +++ b/pkg/logs/graphql_source.go @@ -12,6 +12,24 @@ import ( // --history bounds the backfill only (not every poll). const FollowPageSize = 200 +// MaxFollowPollFailures bounds how many consecutive failed polls Follow absorbs +// before giving up. A transient failure — a Hasura 502, a suspended laptop, a VPN +// blip — must not end a tail the user has had open for hours, but a backend that +// is genuinely gone must still surface so the command can exit non-zero. +const MaxFollowPollFailures = 10 + +// GraphQLOption configures a GraphQLSource. +type GraphQLOption func(*GraphQLSource) + +// WithFollowErrorHandler installs a callback invoked once for every failed poll +// that Follow retries, so the command layer can print the warning line the +// design spec asks for while the loop continues. The error Follow eventually +// returns after MaxFollowPollFailures consecutive failures is not passed to the +// handler: reporting that one belongs to Follow's caller. +func WithFollowErrorHandler(fn func(error)) GraphQLOption { + return func(s *GraphQLSource) { s.onFollowError = fn } +} + // LogLister is the subset of the datastore this source needs. // cmdutil.DatastoreInterface satisfies it. type LogLister interface { @@ -26,16 +44,21 @@ type LogLister interface { // backing GraphQL query exposes no equivalent parameters, so callers that need // those filters must apply them client-side to the returned entries. type GraphQLSource struct { - lister LogLister - pollInterval time.Duration + lister LogLister + pollInterval time.Duration + onFollowError func(error) } // NewGraphQLSource returns a source backed by the datastore. -func NewGraphQLSource(l LogLister, pollInterval time.Duration) *GraphQLSource { +func NewGraphQLSource(l LogLister, pollInterval time.Duration, opts ...GraphQLOption) *GraphQLSource { if pollInterval <= 0 { pollInterval = time.Second } - return &GraphQLSource{lister: l, pollInterval: pollInterval} + s := &GraphQLSource{lister: l, pollInterval: pollInterval} + for _, o := range opts { + o(s) + } + return s } // Name identifies the source in messages and --source. @@ -45,7 +68,9 @@ func (s *GraphQLSource) Name() string { return "graphql" } func (s *GraphQLSource) Caps() Caps { return Caps{Replicas: false, Push: false} } // History returns one page of entries newer than q.From, newest-first, dropping -// anything after q.To when set. +// anything after q.To when set. When the page came back full and q.To discarded +// every row, Page.WindowTruncated says so: the caller cannot tell an empty +// window apart from an unreachable one otherwise. func (s *GraphQLSource) History(ctx context.Context, q Query) (Page, error) { if q.Cursor != "" { return Page{}, ErrPagingUnsupported @@ -56,20 +81,36 @@ func (s *GraphQLSource) History(ctx context.Context, q Query) (Page, error) { } rows, err := s.lister.ListLogsByInstanceID(ctx, q.InstanceID, limit, q.From) if err != nil { - return Page{}, fmt.Errorf("failed to list logs: %w", err) + // Returned unwrapped on purpose: the caller names the step that failed, + // and adding a prefix here produced "failed to fetch log history: failed + // to list logs: ..." for the user. + return Page{}, err } entries := make([]Entry, 0, len(rows)) + discarded := 0 for _, row := range rows { if !q.To.IsZero() && row.Timestamp.After(q.To) { + discarded++ continue } entries = append(entries, toEntry(row)) } - return Page{Entries: entries, HasMore: false}, nil + // The backing query can only bound From, ordered newest-first, so the server + // truncates from the newest end. A full page whose every row q.To rejected + // means the page never reached back into the window; older in-window entries + // may exist and this source cannot ask for them (that needs a + // timestamp: {_lt: ...} bound). + truncated := discarded > 0 && discarded == len(rows) && len(rows) == limit + return Page{Entries: entries, HasMore: false, WindowTruncated: truncated}, nil } // Follow backfills once using q.Limit, then polls for newer entries, emitting // them oldest-first on out until ctx is cancelled. +// +// A failed poll is not fatal: it is handed to the WithFollowErrorHandler callback +// and retried on the next tick, because one bad response must not end a live +// tail. Only MaxFollowPollFailures consecutive failures — a backend that is +// genuinely unreachable — return an error. func (s *GraphQLSource) Follow(ctx context.Context, q Query, out chan<- Entry) error { limit := q.Limit if limit <= 0 { @@ -79,26 +120,38 @@ func (s *GraphQLSource) Follow(ctx context.Context, q Query, out chan<- Entry) e ticker := time.NewTicker(s.pollInterval) defer ticker.Stop() + failures := 0 for { rows, err := s.lister.ListLogsByInstanceID(ctx, q.InstanceID, limit, cursor) - if err != nil { - if ctx.Err() != nil { - return nil + switch { + case err != nil && ctx.Err() != nil: + // Cancellation is a clean stop, never a fetch failure. + return nil + case err != nil: + failures++ + if failures >= MaxFollowPollFailures { + return fmt.Errorf("log polling failed %d times consecutively: %w", failures, err) } - return fmt.Errorf("failed to list logs: %w", err) - } - // Datastore returns newest-first; emit oldest-first. - for i := len(rows) - 1; i >= 0; i-- { - select { - case out <- toEntry(rows[i]): - case <-ctx.Done(): - return nil + // Report and retry: the backfill limit is kept so a first-poll + // failure does not shrink the history the user asked for. + if s.onFollowError != nil { + s.onFollowError(err) } - if rows[i].Timestamp.After(cursor) { - cursor = rows[i].Timestamp + default: + failures = 0 + // Datastore returns newest-first; emit oldest-first. + for i := len(rows) - 1; i >= 0; i-- { + select { + case out <- toEntry(rows[i]): + case <-ctx.Done(): + return nil + } + if rows[i].Timestamp.After(cursor) { + cursor = rows[i].Timestamp + } } + limit = FollowPageSize } - limit = FollowPageSize select { case <-ctx.Done(): diff --git a/pkg/logs/graphql_source_test.go b/pkg/logs/graphql_source_test.go index 676c38c..4fba97c 100644 --- a/pkg/logs/graphql_source_test.go +++ b/pkg/logs/graphql_source_test.go @@ -44,6 +44,29 @@ func (f *fakeLister) ListLogsByInstanceID(_ context.Context, id string, limit in return page, nil } +// listerStep is one scripted result for scriptedLister. +type listerStep struct { + page []api.Log + err error +} + +// scriptedLister serves a scripted sequence of results, repeating the last step +// forever once the script runs out. It lets a Follow test interleave transient +// failures with successful polls. +type scriptedLister struct { + steps []listerStep + calls int +} + +func (l *scriptedLister) ListLogsByInstanceID(_ context.Context, _ string, _ int, _ time.Time) ([]api.Log, error) { + i := l.calls + l.calls++ + if i >= len(l.steps) { + i = len(l.steps) - 1 + } + return l.steps[i].page, l.steps[i].err +} + // startFollow runs Follow on a goroutine and returns its error channel. func startFollow(ctx context.Context, s *GraphQLSource, q Query, out chan Entry) <-chan error { done := make(chan error, 1) @@ -115,14 +138,79 @@ func TestGraphQLSource_HistoryRejectsCursor(t *testing.T) { require.ErrorIs(t, err, ErrPagingUnsupported) } -func TestGraphQLSource_HistoryWrapsListerError(t *testing.T) { +// TestGraphQLSource_HistoryFlagsAWindowTruncatedByTheLimit is the source half of +// blocker 2. The backing query can only say "newer than From" with a limit, +// ordered newest-first, so To is enforced by discarding rows here. When the +// server fills the page from the newest end, every row can be newer than To and +// the whole page is dropped — indistinguishable from an empty window unless the +// source says so. +func TestGraphQLSource_HistoryFlagsAWindowTruncatedByTheLimit(t *testing.T) { + t0 := time.Date(2026, 8, 2, 10, 0, 0, 0, time.UTC) + to := t0.Add(time.Minute) + // A full page (len == Limit) in which every row is newer than To. + saturated := []api.Log{ + {LogLevel: "info", Message: "n3", Timestamp: to.Add(3 * time.Minute)}, + {LogLevel: "info", Message: "n2", Timestamp: to.Add(2 * time.Minute)}, + {LogLevel: "info", Message: "n1", Timestamp: to.Add(1 * time.Minute)}, + } + + t.Run("full page entirely newer than To is flagged", func(t *testing.T) { + s := NewGraphQLSource(&fakeLister{pages: [][]api.Log{saturated}}, time.Second) + page, err := s.History(context.Background(), Query{InstanceID: "i", From: t0, To: to, Limit: 3}) + require.NoError(t, err) + require.Empty(t, page.Entries) + require.True(t, page.WindowTruncated, + "a full page discarded in its entirety means in-window entries may exist below it") + }) + + t.Run("short page is not flagged", func(t *testing.T) { + s := NewGraphQLSource(&fakeLister{pages: [][]api.Log{saturated}}, time.Second) + page, err := s.History(context.Background(), Query{InstanceID: "i", From: t0, To: to, Limit: 10}) + require.NoError(t, err) + require.Empty(t, page.Entries) + require.False(t, page.WindowTruncated, + "the server had room to spare, so the window really is empty") + }) + + t.Run("full page with survivors is not flagged", func(t *testing.T) { + rows := []api.Log{ + {LogLevel: "info", Message: "newer", Timestamp: to.Add(time.Minute)}, + {LogLevel: "info", Message: "kept", Timestamp: t0.Add(30 * time.Second)}, + } + s := NewGraphQLSource(&fakeLister{pages: [][]api.Log{rows}}, time.Second) + page, err := s.History(context.Background(), Query{InstanceID: "i", From: t0, To: to, Limit: 2}) + require.NoError(t, err) + require.Len(t, page.Entries, 1) + require.False(t, page.WindowTruncated, "the page reached back inside the window") + }) + + t.Run("no To means no upper bound to truncate against", func(t *testing.T) { + s := NewGraphQLSource(&fakeLister{pages: [][]api.Log{saturated}}, time.Second) + page, err := s.History(context.Background(), Query{InstanceID: "i", From: t0, Limit: 3}) + require.NoError(t, err) + require.Len(t, page.Entries, 3) + require.False(t, page.WindowTruncated) + }) + + t.Run("empty page is not flagged", func(t *testing.T) { + s := NewGraphQLSource(&fakeLister{}, time.Second) + page, err := s.History(context.Background(), Query{InstanceID: "i", From: t0, To: to, Limit: 0}) + require.NoError(t, err) + require.Empty(t, page.Entries) + require.False(t, page.WindowTruncated) + }) +} + +// TestGraphQLSource_HistoryReturnsTheListerErrorUnprefixed pins review finding 7: +// the command layer already says "failed to fetch log history", so a +// "failed to list logs" prefix here produced a doubled message. +func TestGraphQLSource_HistoryReturnsTheListerErrorUnprefixed(t *testing.T) { sentinel := errors.New("boom") s := NewGraphQLSource(&fakeLister{err: sentinel}, time.Second) _, err := s.History(context.Background(), Query{InstanceID: "i"}) - require.ErrorIs(t, err, sentinel, "lister error must be wrapped with %w") - // ErrorIs alone also passes for a bare `return err`; the prefix proves the - // error is actually wrapped with context. - require.Contains(t, err.Error(), "failed to list logs", "wrapper message must be preserved") + require.ErrorIs(t, err, sentinel, "the lister error must reach the caller") + require.Equal(t, sentinel.Error(), err.Error(), + "the source must not add a prefix; its caller names the step that failed") } func TestGraphQLSource_HistoryMapsAllEntryFields(t *testing.T) { @@ -204,7 +292,7 @@ func TestGraphQLSource_FollowEmitsOldestFirstAndAdvancesToNewest(t *testing.T) { require.Equal(t, t0.Add(3*time.Second), lister.calls[1], "cursor advances to newest timestamp seen") } -func TestGraphQLSource_FollowWrapsListerErrorWhenContextLive(t *testing.T) { +func TestGraphQLSource_FollowSurfacesAPersistentListerError(t *testing.T) { sentinel := errors.New("boom") lister := &fakeLister{err: sentinel} s := NewGraphQLSource(lister, time.Millisecond) @@ -216,11 +304,113 @@ func TestGraphQLSource_FollowWrapsListerErrorWhenContextLive(t *testing.T) { done := startFollow(ctx, s, Query{InstanceID: "inst-err"}, out) err := waitFollow(t, done) - require.Error(t, err, "a lister error on a live context must surface") + require.Error(t, err, "a lister error that never recovers must surface") require.ErrorIs(t, err, sentinel) - require.Contains(t, err.Error(), "failed to list logs", "wrapper message must be preserved") + require.Contains(t, err.Error(), "consecutive", "the give-up message must say the retries were exhausted") require.NoError(t, ctx.Err(), "context must still be live for this to be meaningful") - require.Equal(t, []string{"inst-err"}, lister.ids, "Query.InstanceID is passed through") + require.Equal(t, "inst-err", lister.ids[0], "Query.InstanceID is passed through") +} + +// TestGraphQLSource_FollowSurvivesATransientListerError is the source half of +// blocker 1: a single failed poll must be reported and retried, not returned. +// One Hasura 502 used to end a tail that had been open for hours. +func TestGraphQLSource_FollowSurvivesATransientListerError(t *testing.T) { + t0 := time.Date(2026, 8, 2, 10, 0, 0, 0, time.UTC) + blip := errors.New("hasura 502") + lister := &scriptedLister{steps: []listerStep{ + {err: blip}, + {page: []api.Log{{LogLevel: "info", Message: "after-the-blip", Timestamp: t0}}}, + {}, + }} + var reported []error + s := NewGraphQLSource(lister, time.Millisecond, + WithFollowErrorHandler(func(err error) { reported = append(reported, err) })) + + ctx, cancel := context.WithTimeout(context.Background(), followTimeout) + defer cancel() + out := make(chan Entry, 4) + done := startFollow(ctx, s, Query{InstanceID: "i"}, out) + + require.Equal(t, "after-the-blip", recvEntry(t, out).Message, + "Follow must keep polling after a transient fetch error") + cancel() + require.NoError(t, waitFollow(t, done), "a transient error must not end the stream") + require.Len(t, reported, 1, "the retried failure must be reported exactly once") + require.ErrorIs(t, reported[0], blip) +} + +// TestGraphQLSource_FollowGivesUpAfterConsecutiveFailures pins the other half: +// resilience is bounded, so a genuinely dead backend still exits non-zero. +func TestGraphQLSource_FollowGivesUpAfterConsecutiveFailures(t *testing.T) { + dead := errors.New("hasura unreachable") + lister := &scriptedLister{steps: []listerStep{{err: dead}}} + reported := 0 + s := NewGraphQLSource(lister, time.Millisecond, + WithFollowErrorHandler(func(error) { reported++ })) + + ctx, cancel := context.WithTimeout(context.Background(), followTimeout) + defer cancel() + done := startFollow(ctx, s, Query{InstanceID: "i"}, make(chan Entry, 1)) + + err := waitFollow(t, done) + require.Error(t, err) + require.ErrorIs(t, err, dead) + require.NoError(t, ctx.Err(), "the give-up must not be caused by cancellation") + require.Equal(t, MaxFollowPollFailures, lister.calls, + "Follow retries a bounded number of times before giving up") + require.Equal(t, MaxFollowPollFailures-1, reported, + "every retried failure is reported; the final one is returned instead") +} + +// TestGraphQLSource_FollowResetsTheFailureCountOnSuccess proves the ladder is +// consecutive, not cumulative: an instance that blips once a minute for a day +// must never exhaust it. +func TestGraphQLSource_FollowResetsTheFailureCountOnSuccess(t *testing.T) { + t0 := time.Date(2026, 8, 2, 10, 0, 0, 0, time.UTC) + blip := errors.New("blip") + var steps []listerStep + // Alternate failure/success far more times than the ladder allows. + for i := 0; i < MaxFollowPollFailures*3; i++ { + steps = append(steps, + listerStep{err: blip}, + listerStep{page: []api.Log{{LogLevel: "info", Message: "alive", Timestamp: t0.Add(time.Duration(i) * time.Second)}}}, + ) + } + steps = append(steps, listerStep{}) + lister := &scriptedLister{steps: steps} + s := NewGraphQLSource(lister, time.Microsecond, WithFollowErrorHandler(func(error) {})) + + ctx, cancel := context.WithTimeout(context.Background(), followTimeout) + defer cancel() + out := make(chan Entry, 128) + done := startFollow(ctx, s, Query{InstanceID: "i"}, out) + + for i := 0; i < MaxFollowPollFailures*3; i++ { + require.Equal(t, "alive", recvEntry(t, out).Message) + } + cancel() + require.NoError(t, waitFollow(t, done), "interleaved failures must never exhaust the ladder") +} + +// TestGraphQLSource_FollowErrorHandlerIsOptional pins that a source built +// without a handler still retries rather than panicking on a nil callback. +func TestGraphQLSource_FollowErrorHandlerIsOptional(t *testing.T) { + t0 := time.Date(2026, 8, 2, 10, 0, 0, 0, time.UTC) + lister := &scriptedLister{steps: []listerStep{ + {err: errors.New("blip")}, + {page: []api.Log{{LogLevel: "info", Message: "recovered", Timestamp: t0}}}, + {}, + }} + s := NewGraphQLSource(lister, time.Millisecond) + + ctx, cancel := context.WithTimeout(context.Background(), followTimeout) + defer cancel() + out := make(chan Entry, 4) + done := startFollow(ctx, s, Query{InstanceID: "i"}, out) + + require.Equal(t, "recovered", recvEntry(t, out).Message) + cancel() + require.NoError(t, waitFollow(t, done)) } func TestGraphQLSource_FollowReturnsNilWhenContextCancelledBeforeError(t *testing.T) { diff --git a/pkg/logs/render.go b/pkg/logs/render.go index 3096610..132ea5f 100644 --- a/pkg/logs/render.go +++ b/pkg/logs/render.go @@ -9,9 +9,16 @@ import ( "github.com/cli/cli/v2/pkg/iostreams" ) -// timeLayout is the wall-clock format used for each line. +// timeLayout is the wall-clock format used for each line. It deliberately +// carries no date; DateMarker supplies that once per calendar day instead. const timeLayout = "15:04:05.000" +// dateLayout is the calendar date DateMarker prints. +const dateLayout = "2006-01-02" + +// dateMarkerPrefix distinguishes a date banner from a log line at a glance. +const dateMarkerPrefix = "==> " + // RenderOptions controls line formatting. type RenderOptions struct { // ShowReplica adds the replica short-id column. Callers set this from @@ -21,7 +28,8 @@ type RenderOptions struct { // The Renderer itself does not branch on this flag: callers decide the // format by calling either Line or JSONLine. JSON bool - // UTC prints timestamps in UTC instead of local time. + // UTC prints human-format timestamps in UTC instead of local time. JSONLine + // is always UTC and ignores this flag. UTC bool } @@ -29,6 +37,8 @@ type RenderOptions struct { type Renderer struct { cs *iostreams.ColorScheme opts RenderOptions + // lastDate is the calendar date of the entry DateMarker last marked. + lastDate string } // NewRenderer returns a Renderer using the given colour scheme. @@ -39,11 +49,7 @@ func NewRenderer(cs *iostreams.ColorScheme, opts RenderOptions) *Renderer { // Line renders one entry in the human format, without a trailing newline. It // does not consult RenderOptions.JSON; a caller wanting JSON calls JSONLine. func (r *Renderer) Line(e Entry) string { - ts := e.Timestamp.In(time.Local) - if r.opts.UTC { - ts = e.Timestamp.UTC() - } - out := ts.Format(timeLayout) + " " + out := r.at(e.Timestamp).Format(timeLayout) + " " if r.opts.ShowReplica { out += r.colorReplica(e.ReplicaID) + " " } @@ -51,15 +57,13 @@ func (r *Renderer) Line(e Entry) string { return out } -// JSONLine renders one entry as a single-line JSON object. The timestamp is -// normalized to the same location Line would use, so RenderOptions.UTC applies -// to both formats. The caller's entry is not mutated. +// JSONLine renders one entry as a single-line JSON object with a UTC RFC3339 +// timestamp. Machine-readable output must not vary with the operator's timezone, +// so RenderOptions.UTC governs the human format only and is not consulted here. +// The caller's entry is not mutated. func (r *Renderer) JSONLine(e Entry) (string, error) { out := e - out.Timestamp = e.Timestamp.In(time.Local) - if r.opts.UTC { - out.Timestamp = e.Timestamp.UTC() - } + out.Timestamp = e.Timestamp.UTC() b, err := json.Marshal(out) if err != nil { return "", fmt.Errorf("failed to encode log entry: %w", err) @@ -67,6 +71,33 @@ func (r *Renderer) JSONLine(e Entry) (string, error) { return string(b), nil } +// at converts a timestamp into the zone the human format renders in. +func (r *Renderer) at(ts time.Time) time.Time { + if r.opts.UTC { + return ts.UTC() + } + return ts.In(time.Local) +} + +// DateMarker returns a muted date banner to print immediately before e, or "" +// when e falls on the same calendar date as the entry it last marked. Line +// carries only HH:MM:SS.mmm, so without this the default 300-entry page and any +// multi-day --from/--to window are ambiguous. +// +// It honours RenderOptions.UTC so the banner always names the date the clock +// time on the following lines belongs to. It is human-format only: JSONLine +// already carries a full RFC3339 timestamp per object and must stay one +// machine-readable object per line. The Renderer is rendered from a single +// goroutine in both modes, so the retained date needs no locking. +func (r *Renderer) DateMarker(e Entry) string { + day := r.at(e.Timestamp).Format(dateLayout) + if day == r.lastDate { + return "" + } + r.lastDate = day + return r.cs.Muted(dateMarkerPrefix + day) +} + // colorLevel pads the level to a fixed width and colours it by severity. The // severity match is case-insensitive, but the level is rendered as supplied. func (r *Renderer) colorLevel(level string) string { diff --git a/pkg/logs/render_test.go b/pkg/logs/render_test.go index edb8a53..a7c6c31 100644 --- a/pkg/logs/render_test.go +++ b/pkg/logs/render_test.go @@ -167,20 +167,74 @@ func TestRenderer_LineDefaultsToLocalTime(t *testing.T) { require.Equal(t, want, r.Line(e)) } -// TestRenderer_JSONLineDefaultsToLocalTime is the JSON counterpart: with -// UTC:false the timestamp is converted to time.Local, not left in the entry's -// own zone. -func TestRenderer_JSONLineDefaultsToLocalTime(t *testing.T) { - r := testRenderer(t, RenderOptions{JSON: true}) +// TestRenderer_JSONLineIsAlwaysUTC pins review finding 5: --json is sold as the +// scripting format, so its timestamps must not vary with the operator's TZ. +// Both the UTC:false and UTC:true paths must emit the same instant in UTC. +func TestRenderer_JSONLineIsAlwaysUTC(t *testing.T) { + // A local zone with a non-zero offset, otherwise a UTC CI machine would make + // the assertion vacuous. Not parallel-safe. + origLocal := time.Local + time.Local = time.FixedZone("TEST+09", 9*60*60) + t.Cleanup(func() { time.Local = origLocal }) + ts := time.Date(2026, 8, 2, 16, 23, 1, 0, time.FixedZone("UTC+2", 2*60*60)) + for name, opts := range map[string]RenderOptions{ + "utc flag off": {JSON: true}, + "utc flag on": {JSON: true, UTC: true}, + } { + t.Run(name, func(t *testing.T) { + got, err := testRenderer(t, opts).JSONLine(Entry{Timestamp: ts, Level: "info", Message: "hello"}) + require.NoError(t, err) + require.Contains(t, got, `"timestamp":"2026-08-02T14:23:01Z"`, + "machine-readable output must be UTC RFC3339 regardless of the host timezone") + }) + } +} - got, err := r.JSONLine(Entry{Timestamp: ts, Level: "info", Message: "hello"}) - require.NoError(t, err) +// TestRenderer_DateMarker pins review finding 3: the line format carries only +// HH:MM:SS.mmm, so a date banner is the only thing that keeps multi-day history +// and explicit --from/--to windows unambiguous. +func TestRenderer_DateMarker(t *testing.T) { + r := testRenderer(t, RenderOptions{UTC: true}) + day1 := time.Date(2026, 8, 2, 23, 59, 0, 0, time.UTC) + day2 := time.Date(2026, 8, 3, 0, 0, 1, 0, time.UTC) - wantTS, err := json.Marshal(ts.In(time.Local)) - require.NoError(t, err) - require.Contains(t, got, `"timestamp":`+string(wantTS), - "UTC:false must render the timestamp in time.Local") + require.Equal(t, "==> 2026-08-02", r.DateMarker(Entry{Timestamp: day1}), + "the first entry always gets a marker") + require.Equal(t, "", r.DateMarker(Entry{Timestamp: day1.Add(30 * time.Second)}), + "the same calendar date must not be repeated") + require.Equal(t, "==> 2026-08-03", r.DateMarker(Entry{Timestamp: day2}), + "a date change must emit a new marker") + require.Equal(t, "", r.DateMarker(Entry{Timestamp: day2.Add(time.Hour)})) + require.Equal(t, "==> 2026-08-02", r.DateMarker(Entry{Timestamp: day1}), + "going back a day is still a change") +} + +// TestRenderer_DateMarkerHonoursUTC pins that the banner reports the same +// calendar day the line's clock time belongs to, in whichever zone Line uses. +func TestRenderer_DateMarkerHonoursUTC(t *testing.T) { + origLocal := time.Local + time.Local = time.FixedZone("TEST+09", 9*60*60) + t.Cleanup(func() { time.Local = origLocal }) + + // 2026-08-02T23:30Z is already 2026-08-03 in TEST+09. + ts := time.Date(2026, 8, 2, 23, 30, 0, 0, time.UTC) + + require.Equal(t, "==> 2026-08-02", testRenderer(t, RenderOptions{UTC: true}).DateMarker(Entry{Timestamp: ts}), + "--utc must date the entry in UTC") + require.Equal(t, "==> 2026-08-03", testRenderer(t, RenderOptions{}).DateMarker(Entry{Timestamp: ts}), + "without --utc the marker must follow the local date Line prints") +} + +// TestRenderer_DateMarkerIsMuted pins that the banner is styled with the muted +// colour so it reads as a separator rather than as a log line. +func TestRenderer_DateMarkerIsMuted(t *testing.T) { + cs := &iostreams.ColorScheme{Enabled: true} + r := NewRenderer(cs, RenderOptions{UTC: true}) + marker := r.DateMarker(Entry{Timestamp: time.Date(2026, 8, 2, 10, 0, 0, 0, time.UTC)}) + + require.Contains(t, marker, ansiPrefix, "a colour-enabled scheme must style the marker") + require.Equal(t, ansiCodes(cs.Muted("x")), ansiCodes(marker), "the marker uses the muted colour") } func TestRenderer_LineLevels(t *testing.T) { diff --git a/pkg/logs/source.go b/pkg/logs/source.go index 4fa3d27..983f999 100644 --- a/pkg/logs/source.go +++ b/pkg/logs/source.go @@ -47,6 +47,11 @@ type Page struct { // Cursor is passed back as Query.Cursor to fetch the next older page. Cursor string HasMore bool + // WindowTruncated reports that the source filled this page from the newest + // end and Query.To then discarded all of it, so entries inside the requested + // window may exist older than anything the page could reach. Sources that can + // express an upper bound server-side never set it. + WindowTruncated bool } // Caps describes what a Source can do, so callers can enable or hide features diff --git a/vcr/instance/log/log.go b/vcr/instance/log/log.go index d787ca9..32db7b7 100644 --- a/vcr/instance/log/log.go +++ b/vcr/instance/log/log.go @@ -99,8 +99,10 @@ func newLogCmd(f cmdutil.Factory, use string, aliases []string, invocation strin Use (?i) inside a pattern for case-insensitive matching. OUTPUT - Each line is: HH:MM:SS.mmm level message - --json prints one JSON object per line for scripting. + Each line is: HH:MM:SS.mmm level message, preceded by a + "==> YYYY-MM-DD" marker whenever the calendar date changes. + --json prints one JSON object per line for scripting, always with + UTC timestamps so output does not vary by host timezone. `), Args: cobra.MaximumNArgs(0), Example: fmt.Sprintf(heredoc.Doc(` @@ -146,6 +148,30 @@ func newLogCmd(f cmdutil.Factory, use string, aliases []string, invocation strin return cmd } +// validateFlags rejects numeric flag values that cannot mean what the user +// typed. Both were silently rewritten to a default deep inside pkg/logs, so +// --history 0 fetched 200 entries and --buffer 0 retained 5000. +func validateFlags(opts *Options) error { + if opts.Limit <= 0 { + return fmt.Errorf("--history must be a positive number, got %d", opts.Limit) + } + if opts.BufferSize <= 0 { + return fmt.Errorf("--buffer must be a positive number, got %d", opts.BufferSize) + } + return nil +} + +// flagPatternError re-frames a logs.Filter pattern error so it names the flag +// the user actually typed. Filter reports "invalid include pattern", which +// describes its own field and reads like a typo to someone who typed --grep. +func flagPatternError(flag, pattern string, err error) error { + cause := errors.Unwrap(err) + if cause == nil { + cause = err + } + return fmt.Errorf("invalid %s %q: %w", flag, pattern, cause) +} + // buildQueryAndFilter converts flags into a source query and a filter, failing // fast on contradictory or malformed input. func buildQueryAndFilter(opts *Options) (logs.Query, *logs.Filter, error) { @@ -185,19 +211,27 @@ func buildQueryAndFilter(opts *Options) (logs.Query, *logs.Filter, error) { f.MinLevel = lvl } if err := f.SetInclude(opts.Grep); err != nil { - return logs.Query{}, nil, err + return logs.Query{}, nil, flagPatternError("--grep", opts.Grep, err) } if err := f.SetExclude(opts.Exclude); err != nil { - return logs.Query{}, nil, err + return logs.Query{}, nil, flagPatternError("--exclude", opts.Exclude, err) } return q, f, nil } // newSource picks the log source. Phase 3 adds the SSE-backed "stream" source. +// +// The source is given a handler for retried fetch failures so a transient error +// while following prints a warning to ErrOut and the stream carries on, rather +// than ending a long-running tail with a non-zero exit. func newSource(opts *Options) (logs.Source, error) { switch opts.SourceName { case "", "auto", "graphql": - return logs.NewGraphQLSource(opts.Datastore(), TickerInterval), nil + return logs.NewGraphQLSource(opts.Datastore(), TickerInterval, + logs.WithFollowErrorHandler(func(err error) { + io := opts.IOStreams() + fmt.Fprintf(io.ErrOut, "%s Error fetching logs: %v\n", io.ColorScheme().WarningIcon(), err) + })), nil default: return nil, fmt.Errorf("unknown --source %q: want auto or graphql", opts.SourceName) } @@ -208,6 +242,9 @@ func runLog(opts *Options) error { if err := cmdutil.ValidateFlags(opts.InstanceID, opts.InstanceName, opts.ProjectName); err != nil { return fmt.Errorf("failed to validate flags: %w", err) } + if err := validateFlags(opts); err != nil { + return fmt.Errorf("failed to validate flags: %w", err) + } q, filter, err := buildQueryAndFilter(opts) if err != nil { @@ -277,8 +314,18 @@ func runHistory(src logs.Source, opts *Options, q logs.Query, filter *logs.Filte emit(opts, renderer, e) shown++ } - if shown == 0 { - c := io.ColorScheme() + c := io.ColorScheme() + switch { + case page.WindowTruncated: + // The source filled the page from the newest end and --to rejected all of + // it, so the window was never reached. Saying "no matching log entries" + // here would be a confidently wrong answer. Paging older than the page + // needs a timestamp: {_lt: ...} bound, which lands in a later phase. + fmt.Fprintf(io.ErrOut, + "%s --history %d was filled entirely with entries newer than --to, so the requested window may contain older entries that were not fetched.\n"+ + " Retry with a larger --history or a later --from.\n", + c.WarningIcon(), q.Limit) + case shown == 0: fmt.Fprintf(io.ErrOut, "%s no matching log entries in range\n", c.WarningIcon()) } return nil @@ -330,6 +377,10 @@ func runFollow(src logs.Source, opts *Options, q logs.Query, filter *logs.Filter for { select { case <-interrupt: + // Cancel first: draining a channel a live producer is still filling + // can never finish, and the longer this branch runs the longer a + // second Ctrl+C is swallowed by the handler still installed below. + cancel() drain() fmt.Fprintf(io.ErrOut, "\n%s stopped\n", c.SuccessIcon()) return nil @@ -357,6 +408,9 @@ func emit(opts *Options, renderer *logs.Renderer, e logs.Entry) { fmt.Fprintln(io.Out, line) return } + if marker := renderer.DateMarker(e); marker != "" { + fmt.Fprintln(io.Out, marker) + } fmt.Fprintln(io.Out, renderer.Line(e)) } diff --git a/vcr/instance/log/log_test.go b/vcr/instance/log/log_test.go index b7e069d..b940233 100644 --- a/vcr/instance/log/log_test.go +++ b/vcr/instance/log/log_test.go @@ -445,7 +445,12 @@ func Test_runFollow_isNotBoundedByGlobalTimeout(t *testing.T) { require.False(t, src.hadDeadline, "follow context must not carry the global --timeout deadline") } -func Test_runFollow_wrapsSourceError(t *testing.T) { +// Test_runFollow_surfacesPersistentSourceError pins the command half of blocker +// 1. Transient poll failures are absorbed and retried inside the source (see +// TestGraphQLSource_FollowSurvivesATransientListerError), so by the time Follow +// returns an error it has given up — which is genuinely fatal and must exit +// non-zero rather than look like a clean stop. +func Test_runFollow_surfacesPersistentSourceError(t *testing.T) { ios, _, _, _ := iostreams.Test() f := testutil.DefaultFactoryMock(t, ios, nil, nil, nil, nil, nil, nil) opts := &Options{Factory: f, Follow: true, BufferSize: 10} @@ -458,6 +463,55 @@ func Test_runFollow_wrapsSourceError(t *testing.T) { require.Contains(t, err.Error(), "failed to stream logs: transport died") } +// Test_runLog_followSurvivesATransientFetchError is blocker 1 end-to-end through +// the real GraphQL source: one failed poll must warn on ErrOut and keep the tail +// alive. Before the fix a single Hasura 502 ended a long-running `vcr logs -f` +// with exit 1, contradicting both the old command and the design spec +// ("printed to ErrOut with the warning icon; the loop continues"). +func Test_runLog_followSurvivesATransientFetchError(t *testing.T) { + ctrl := gomock.NewController(t) + datastoreMock := mocks.NewMockDatastoreInterface(ctrl) + datastoreMock.EXPECT(). + GetInstanceByID(gomock.Any(), "abc-123"). + Times(1). + Return(api.Instance{ID: "abc-123"}, nil) + + call := 0 + datastoreMock.EXPECT(). + ListLogsByInstanceID(gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any()). + MinTimes(3). + DoAndReturn(func(_ context.Context, _ string, _ int, _ time.Time) ([]api.Log, error) { + call++ + switch call { + case 1: + return nil, errors.New("hasura 502") + case 2: + return []api.Log{{Timestamp: time.Now(), SourceType: "application", LogLevel: "info", Message: "survived-the-blip"}}, nil + default: + // The entry above is already on the channel; stop the session. + p, _ := os.FindProcess(os.Getpid()) + _ = p.Signal(os.Interrupt) + return nil, nil + } + }) + + ios, _, stdout, stderr := iostreams.Test() + f := testutil.DefaultFactoryMock(t, ios, nil, nil, datastoreMock, nil, nil, nil) + + cmd := NewCmdInstanceLog(f) + cmd.SetArgs([]string{"--id=abc-123", "--follow"}) + cmd.SetIn(&bytes.Buffer{}) + cmd.SetOut(io.Discard) + cmd.SetErr(io.Discard) + + _, err := cmd.ExecuteC() + require.NoError(t, err, "a transient fetch error must not end --follow with a non-zero exit") + require.Contains(t, stdout.String(), "survived-the-blip", "polling must continue past the failure") + require.Contains(t, stderr.String(), "hasura 502", "the failure must still be reported") + require.Contains(t, stderr.String(), "!", "the report uses the warning icon") + require.NotContains(t, stdout.String(), "hasura 502", "warnings belong on ErrOut") +} + // Test_runHistory_ordering pins that a history page (newest-first from the // source) is printed chronologically by default and newest-first with --reverse. func Test_runHistory_ordering(t *testing.T) { @@ -699,8 +753,10 @@ func Test_runLog_historyErrorIsReportedOnce(t *testing.T) { "the command layer must name the step that failed") require.Contains(t, err.Error(), "datastore unreachable", "the underlying cause must survive wrapping") - require.Equal(t, 1, strings.Count(err.Error(), "failed to list logs"), - "the command wrapper must not repeat the source layer's phrasing") + require.NotContains(t, err.Error(), "failed to list logs", + "the source must not add a prefix the command already supplies") + require.Equal(t, 1, strings.Count(err.Error(), "failed to "), + "the user must see one failure prefix, not two") require.Empty(t, stdout.String(), "nothing should be printed when the fetch fails") } @@ -894,3 +950,360 @@ func TestLogCmd_ExamplesMatchTheirOwnInvocation(t *testing.T) { require.NotContains(t, topLevel.Example, "%!") require.NotContains(t, nested.Example, "%!") } + +// Test_validateFlags pins review finding 10: --history 0 used to become 200 and +// --buffer 0 used to become 5000, deep inside pkg/logs. Silently substituting a +// default for a value the user typed is worse than refusing it. +func Test_validateFlags(t *testing.T) { + t.Run("accepts the defaults", func(t *testing.T) { + require.NoError(t, validateFlags(&Options{Limit: DefaultHistoryLimit, BufferSize: logs.DefaultBufferSize})) + }) + + for name, limit := range map[string]int{"zero": 0, "negative": -1} { + t.Run("rejects "+name+" history", func(t *testing.T) { + err := validateFlags(&Options{Limit: limit, BufferSize: logs.DefaultBufferSize}) + require.Error(t, err) + require.Contains(t, err.Error(), "--history") + require.Contains(t, err.Error(), "positive") + }) + t.Run("rejects "+name+" buffer", func(t *testing.T) { + err := validateFlags(&Options{Limit: DefaultHistoryLimit, BufferSize: limit}) + require.Error(t, err) + require.Contains(t, err.Error(), "--buffer") + require.Contains(t, err.Error(), "positive") + }) + } +} + +// Test_runLog_rejectsNonPositiveSizes drives the same rejection through the real +// command so the error reaches the user with a non-zero exit. +func Test_runLog_rejectsNonPositiveSizes(t *testing.T) { + for _, tt := range []struct{ args, want string }{ + {"--history=0", "--history"}, + {"--buffer=0", "--buffer"}, + } { + t.Run(tt.args, func(t *testing.T) { + ctrl := gomock.NewController(t) + datastoreMock := mocks.NewMockDatastoreInterface(ctrl) + // Nothing may be fetched: the flags are rejected before any request. + datastoreMock.EXPECT().GetInstanceByID(gomock.Any(), gomock.Any()).Times(0) + datastoreMock.EXPECT().ListLogsByInstanceID(gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any()).Times(0) + + ios, _, _, _ := iostreams.Test() + f := testutil.DefaultFactoryMock(t, ios, nil, nil, datastoreMock, nil, nil, nil) + + cmd := NewCmdInstanceLog(f) + cmd.SetArgs([]string{"--id=abc-123", tt.args}) + cmd.SetIn(&bytes.Buffer{}) + cmd.SetOut(io.Discard) + cmd.SetErr(io.Discard) + + _, err := cmd.ExecuteC() + require.Error(t, err) + require.Contains(t, err.Error(), "failed to validate flags: ") + require.Contains(t, err.Error(), tt.want) + }) + } +} + +// Test_buildQueryAndFilter_patternErrorsNameTheFlag pins review finding 6: an +// invalid --grep reported "invalid include pattern", naming Filter's internal +// term rather than the flag the user typed. +func Test_buildQueryAndFilter_patternErrorsNameTheFlag(t *testing.T) { + t.Run("grep", func(t *testing.T) { + _, _, err := buildQueryAndFilter(&Options{Grep: "("}) + require.Error(t, err) + require.Contains(t, err.Error(), `invalid --grep "("`) + require.NotContains(t, err.Error(), "include pattern", + "the user never typed the word include") + require.Contains(t, err.Error(), "missing closing )", + "the regexp cause must survive re-framing") + }) + + t.Run("exclude", func(t *testing.T) { + _, _, err := buildQueryAndFilter(&Options{Exclude: "["}) + require.Error(t, err) + require.Contains(t, err.Error(), `invalid --exclude "["`) + require.NotContains(t, err.Error(), "exclude pattern", + "the flag name, not Filter's internal wording") + }) +} + +// Test_runHistory_warnsWhenTheWindowWasTruncated is blocker 2 at the command +// boundary: a page the server filled entirely from the newest end, all of which +// --to discarded, must not be reported as an empty window. +func Test_runHistory_warnsWhenTheWindowWasTruncated(t *testing.T) { + ios, _, stdout, stderr := iostreams.Test() + f := testutil.DefaultFactoryMock(t, ios, nil, nil, nil, nil, nil, nil) + opts := &Options{Factory: f, BufferSize: 10, Limit: 3, To: "2026-08-02T10:01:00Z"} + src := &fakeFollowSource{historyPage: logs.Page{WindowTruncated: true}} + + err := runHistory(src, opts, logs.Query{Limit: 3}, &logs.Filter{}, + logs.NewRenderer(ios.ColorScheme(), logs.RenderOptions{UTC: true}), logs.NewBuffer(10), logs.NewRegistry()) + require.NoError(t, err) + + require.Empty(t, stdout.String(), "stdout stays clean for pipes") + warn := stderr.String() + require.NotContains(t, warn, "no matching log entries in range", + "claiming the window is empty is exactly the wrong answer here") + require.Contains(t, warn, "--to", "the warning must name the bound that discarded the page") + require.Contains(t, warn, "--history", "and suggest raising the fetch size") + require.Contains(t, warn, "--from", "and suggest a later window start") + require.Contains(t, warn, "3", "the current --history value helps the user pick a bigger one") +} + +// Test_runLog_toWindowSaturatedByHistoryWarns is blocker 2 end-to-end through the +// real GraphQL source: --from/--to over a busy instance, where more entries exist +// since --from than --history allows, so every row the server returns is newer +// than --to. Before the fix the user got "no matching log entries in range" and +// exit 0, and reasonably concluded the hour they asked about was quiet. +func Test_runLog_toWindowSaturatedByHistoryWarns(t *testing.T) { + from := time.Date(2026, 8, 2, 10, 0, 0, 0, time.UTC) + to := from.Add(time.Hour) + + ctrl := gomock.NewController(t) + datastoreMock := mocks.NewMockDatastoreInterface(ctrl) + datastoreMock.EXPECT(). + GetInstanceByID(gomock.Any(), "abc-123"). + Times(1). + Return(api.Instance{ID: "abc-123"}, nil) + // The server honours only `timestamp > from` with a limit, newest-first, so + // it fills the page from the newest end — hours past --to. + datastoreMock.EXPECT(). + ListLogsByInstanceID(gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any()). + Times(1). + Return([]api.Log{ + {Timestamp: to.Add(3 * time.Hour), SourceType: "application", LogLevel: "info", Message: "way-newer-3"}, + {Timestamp: to.Add(2 * time.Hour), SourceType: "application", LogLevel: "info", Message: "way-newer-2"}, + }, nil) + + ios, _, stdout, stderr := iostreams.Test() + f := testutil.DefaultFactoryMock(t, ios, nil, nil, datastoreMock, nil, nil, nil) + + cmd := NewCmdInstanceLog(f) + cmd.SetArgs([]string{ + "--id=abc-123", + "--from=" + from.Format(time.RFC3339), + "--to=" + to.Format(time.RFC3339), + "--history=2", + }) + cmd.SetIn(&bytes.Buffer{}) + cmd.SetOut(io.Discard) + cmd.SetErr(io.Discard) + + _, err := cmd.ExecuteC() + require.NoError(t, err) + require.Empty(t, stdout.String(), "entries outside the window must not be printed") + + warn := stderr.String() + require.NotContains(t, warn, "no matching log entries in range", + "the window is not known to be empty; the page never reached it") + require.Contains(t, warn, "--history", "the warning must be actionable") +} + +// Test_dateMarkerAppearsInBothModes pins review finding 3. The line format is +// HH:MM:SS.mmm, so without a date banner the default mode's 300 entries and any +// --from/--to window spanning days are ambiguous. +func Test_dateMarkerAppearsInBothModes(t *testing.T) { + day1 := time.Date(2026, 8, 2, 23, 58, 0, 0, time.UTC) + // newest-first, as a source returns it + page := logs.Page{Entries: []logs.Entry{ + {Timestamp: day1.Add(4 * time.Minute), Level: "info", Message: "next-day-late"}, + {Timestamp: day1.Add(3 * time.Minute), Level: "info", Message: "next-day-early"}, + {Timestamp: day1.Add(time.Minute), Level: "info", Message: "same-day-late"}, + {Timestamp: day1, Level: "info", Message: "same-day-early"}, + }} + + assertMarkers := func(t *testing.T, out string) { + t.Helper() + require.Equal(t, 1, strings.Count(out, "==> 2026-08-02"), + "exactly one marker for the first date, not one per entry") + require.Equal(t, 1, strings.Count(out, "==> 2026-08-03"), + "exactly one marker on the date change") + require.Less(t, strings.Index(out, "==> 2026-08-02"), strings.Index(out, "same-day-early"), + "the marker precedes the first entry of its date") + require.Less(t, strings.Index(out, "same-day-late"), strings.Index(out, "==> 2026-08-03"), + "the second marker appears only when the date rolls over") + require.Less(t, strings.Index(out, "==> 2026-08-03"), strings.Index(out, "next-day-early")) + } + + t.Run("history mode", func(t *testing.T) { + ios, _, stdout, _ := iostreams.Test() + f := testutil.DefaultFactoryMock(t, ios, nil, nil, nil, nil, nil, nil) + opts := &Options{Factory: f, BufferSize: 10, Limit: 10} + + err := runHistory(&fakeFollowSource{historyPage: page}, opts, logs.Query{}, &logs.Filter{}, + logs.NewRenderer(ios.ColorScheme(), logs.RenderOptions{UTC: true}), logs.NewBuffer(10), logs.NewRegistry()) + require.NoError(t, err) + assertMarkers(t, stdout.String()) + }) + + t.Run("follow mode", func(t *testing.T) { + ios, _, stdout, _ := iostreams.Test() + f := testutil.DefaultFactoryMock(t, ios, nil, nil, nil, nil, nil, nil) + opts := &Options{Factory: f, Follow: true, BufferSize: 10, Limit: 10} + + // Follow delivers oldest-first, which is what history prints too. + chronological := make([]logs.Entry, 0, len(page.Entries)) + for i := len(page.Entries) - 1; i >= 0; i-- { + chronological = append(chronological, page.Entries[i]) + } + + err := runFollowWithTimeout(t, &fakeFollowSource{emit: chronological}, opts, &logs.Filter{}, + logs.NewRenderer(ios.ColorScheme(), logs.RenderOptions{UTC: true})) + require.NoError(t, err) + assertMarkers(t, stdout.String()) + }) + + t.Run("json mode has no markers", func(t *testing.T) { + ios, _, stdout, _ := iostreams.Test() + f := testutil.DefaultFactoryMock(t, ios, nil, nil, nil, nil, nil, nil) + opts := &Options{Factory: f, BufferSize: 10, Limit: 10, JSONOut: true} + + err := runHistory(&fakeFollowSource{historyPage: page}, opts, logs.Query{}, &logs.Filter{}, + logs.NewRenderer(ios.ColorScheme(), logs.RenderOptions{UTC: true, JSON: true}), logs.NewBuffer(10), logs.NewRegistry()) + require.NoError(t, err) + + out := stdout.String() + require.NotContains(t, out, "==>", "machine-readable output must stay one JSON object per line") + for _, line := range strings.Split(strings.TrimSpace(out), "\n") { + require.True(t, strings.HasPrefix(line, "{"), "every line must be a JSON object, got %q", line) + } + }) + + t.Run("respects --utc", func(t *testing.T) { + origLocal := time.Local + time.Local = time.FixedZone("TEST+09", 9*60*60) + t.Cleanup(func() { time.Local = origLocal }) + + // 2026-08-02T23:58Z is already 2026-08-03 in TEST+09. + ios, _, stdout, _ := iostreams.Test() + f := testutil.DefaultFactoryMock(t, ios, nil, nil, nil, nil, nil, nil) + opts := &Options{Factory: f, BufferSize: 10, Limit: 10} + + single := logs.Page{Entries: []logs.Entry{{Timestamp: day1, Level: "info", Message: "one"}}} + err := runHistory(&fakeFollowSource{historyPage: single}, opts, logs.Query{}, &logs.Filter{}, + logs.NewRenderer(ios.ColorScheme(), logs.RenderOptions{}), logs.NewBuffer(10), logs.NewRegistry()) + require.NoError(t, err) + require.Contains(t, stdout.String(), "==> 2026-08-03", "the marker follows the rendered zone") + }) +} + +// floodingSource fills runFollow's entry channel until a send is left blocked, +// then interrupts the process and keeps sending until its context is cancelled. +// It exists to pin review finding 11: while a sender is blocked on a full +// channel, every receive hands that sender's value straight back into the +// buffer, so the channel is never observed empty and a drain that runs before +// cancel() can never terminate. +type floodingSource struct { + pending <-chan os.Signal + // gate is closed once the interrupt is pending, releasing the render loop. + gate chan struct{} +} + +func (s *floodingSource) Name() string { return "flooding" } +func (s *floodingSource) Caps() logs.Caps { return logs.Caps{} } + +func (s *floodingSource) History(_ context.Context, _ logs.Query) (logs.Page, error) { + return logs.Page{}, nil +} + +func (s *floodingSource) Follow(ctx context.Context, _ logs.Query, out chan<- logs.Entry) error { + entry := func() logs.Entry { + return logs.Entry{Timestamp: time.Now(), Level: "info", Message: "flood"} + } + + // One entry for the render loop to take, so it parks inside the gated Write + // and cannot reach the interrupt branch while the buffer is being filled. + select { + case out <- entry(): + case <-ctx.Done(): + return nil + } + + // Fill the channel buffer completely, detected by the first send that would + // block. Nothing is consuming, so this terminates. + for full := false; !full; { + select { + case out <- entry(): + default: + full = true + } + } + + // Leave a sender blocked on the now-full channel before the loop is released. + done := make(chan struct{}) + go func() { + defer close(done) + for { + select { + case out <- entry(): + case <-ctx.Done(): + return + } + } + }() + + p, err := os.FindProcess(os.Getpid()) + if err != nil { + return err + } + if err := p.Signal(os.Interrupt); err != nil { + return err + } + <-s.pending // the interrupt has reached every registered handler + close(s.gate) + + <-done + return nil +} + +// countingGateWriter holds the render loop still until release is closed, then +// counts every line written. It satisfies the unexported fileWriter interface +// iostreams.IOStreams.Out requires. Only runFollow writes through it, so no +// locking is needed; runFollowWithTimeout's channel receive synchronises the +// read. +type countingGateWriter struct { + release <-chan struct{} + opened sync.Once + lines int +} + +func (w *countingGateWriter) Fd() uintptr { return 1 } + +func (w *countingGateWriter) Write(p []byte) (int, error) { + w.opened.Do(func() { <-w.release }) + w.lines++ + return len(p), nil +} + +// Test_runFollow_interruptCancelsBeforeDraining pins that the interrupt path +// cancels the source before draining. Draining a channel a live producer is +// still filling only ends when the consumer happens to outrun the producer, so +// Ctrl+C keeps rendering entries the user never asked to see — tens of thousands +// of them here — and runFollow's signal handler stays installed for all of it, +// swallowing a second Ctrl+C. Cancelling first bounds the drain to whatever the +// channel already held. +func Test_runFollow_interruptCancelsBeforeDraining(t *testing.T) { + ios, _, _, _ := iostreams.Test() + gate := make(chan struct{}) + out := &countingGateWriter{release: gate} + ios.Out = out + + pending := make(chan os.Signal, 1) + signal.Notify(pending, os.Interrupt) + t.Cleanup(func() { signal.Stop(pending) }) + + f := testutil.DefaultFactoryMock(t, ios, nil, nil, nil, nil, nil, nil) + opts := &Options{Factory: f, Follow: true, BufferSize: 10} + + err := runFollowWithTimeout(t, &floodingSource{pending: pending, gate: gate}, opts, &logs.Filter{}, + logs.NewRenderer(ios.ColorScheme(), logs.RenderOptions{})) + require.NoError(t, err) + + // The channel holds followChanCap entries plus the date marker and the few a + // cancelled producer may still hand over; an order of magnitude of headroom + // keeps this insensitive to scheduling without admitting a runaway drain. + require.Less(t, out.lines, 1000, + "the drain must be bounded by what the channel already held when Ctrl+C arrived") +} From 309d1ec717f4987d0c86040d6a78a62cf43ad14d Mon Sep 17 00:00:00 2001 From: Valdemar Pereira Date: Sun, 2 Aug 2026 23:47:41 +0100 Subject: [PATCH 19/20] docs(root): surface the top-level vcr logs command in root help The generated reference already listed vcr logs under SEE ALSO, but root's hand-written Long and Example only ever showed vcr instance log, so the new entry point was undiscoverable from vcr --help. Adds it to CORE WORKFLOW and to the examples, and regenerates docs/vcr.md. --- docs/vcr.md | 6 +++++- vcr/root/root.go | 6 +++++- vcr/root/root_test.go | 15 +++++++++++++++ 3 files changed, 25 insertions(+), 2 deletions(-) diff --git a/docs/vcr.md b/docs/vcr.md index dfafed1..68f4a0f 100644 --- a/docs/vcr.md +++ b/docs/vcr.md @@ -28,6 +28,7 @@ CORE WORKFLOW • vcr init - Initialize a project from a template • vcr deploy - Deploy your application to VCR • vcr debug - Run your application locally in debug mode + • vcr logs - Tail or search logs from a deployed instance • vcr instance - Manage deployed instances (logs, removal) • vcr secret - Manage secrets for your applications • vcr upgrade - Update the VCR CLI to the latest version @@ -58,7 +59,10 @@ $ vcr deploy $ vcr debug # View logs for a deployed instance -$ vcr instance log --project-name my-project --instance-name dev +$ vcr logs --project-name my-project --instance-name dev + +# Follow logs live (also available as: vcr instance log) +$ vcr logs -p my-project -n dev --follow # Create a secret for your application $ vcr secret create --name MY_API_KEY --value "secret-value" diff --git a/vcr/root/root.go b/vcr/root/root.go index 047b7ae..cae49f9 100644 --- a/vcr/root/root.go +++ b/vcr/root/root.go @@ -60,6 +60,7 @@ func NewCmdRoot(f cmdutil.Factory, version, buildDate, commit string, updateStre • vcr init - Initialize a project from a template • vcr deploy - Deploy your application to VCR • vcr debug - Run your application locally in debug mode + • vcr logs - Tail or search logs from a deployed instance • vcr instance - Manage deployed instances (logs, removal) • vcr secret - Manage secrets for your applications • vcr upgrade - Update the VCR CLI to the latest version @@ -87,7 +88,10 @@ func NewCmdRoot(f cmdutil.Factory, version, buildDate, commit string, updateStre $ vcr debug # View logs for a deployed instance - $ vcr instance log --project-name my-project --instance-name dev + $ vcr logs --project-name my-project --instance-name dev + + # Follow logs live (also available as: vcr instance log) + $ vcr logs -p my-project -n dev --follow # Create a secret for your application $ vcr secret create --name MY_API_KEY --value "secret-value" diff --git a/vcr/root/root_test.go b/vcr/root/root_test.go index 37d45c4..59ca7aa 100644 --- a/vcr/root/root_test.go +++ b/vcr/root/root_test.go @@ -105,3 +105,18 @@ func TestNewCmdRoot_registersTopLevelLogs(t *testing.T) { } require.True(t, found, `root must register a top-level command with Use == "logs"; got %v`, uses) } + +// TestNewCmdRoot_proseMentionsTheTopLevelLogsCommand pins review finding 8: the +// generated docs/vcr.md advertises `vcr logs` under SEE ALSO, but root's +// hand-written Long/Example only ever showed `vcr instance log`, so the new +// entry point was undiscoverable from `vcr --help`. +func TestNewCmdRoot_proseMentionsTheTopLevelLogsCommand(t *testing.T) { + ios, _, _, _ := iostreams.Test() + f := testutil.DefaultFactoryMock(t, ios, nil, nil, nil, nil, nil, nil) + + updateStream := make(chan string, 1) + cmd := NewCmdRoot(f, "0.0.1", "2026-08-02", "abcdef0", updateStream) + + require.Contains(t, cmd.Long, "vcr logs", "CORE WORKFLOW must list the top-level logs command") + require.Contains(t, cmd.Example, "$ vcr logs", "the examples must show a runnable vcr logs invocation") +} From 00194729efd50623f68b856eeedfeca48487d4ca Mon Sep 17 00:00:00 2001 From: Valdemar Pereira Date: Sun, 2 Aug 2026 23:50:33 +0100 Subject: [PATCH 20/20] fix(log): stop wrapping self-describing flag errors in a generic prefix The new validators already name the offending flag, so 'failed to validate flags: --history must be a positive number' doubled up. Keep that prefix only on cmdutil.ValidateFlags, where it is the existing repo convention. --- vcr/instance/log/log.go | 6 +++--- vcr/instance/log/log_test.go | 7 ++++--- 2 files changed, 7 insertions(+), 6 deletions(-) diff --git a/vcr/instance/log/log.go b/vcr/instance/log/log.go index 32db7b7..dfc71e5 100644 --- a/vcr/instance/log/log.go +++ b/vcr/instance/log/log.go @@ -243,12 +243,12 @@ func runLog(opts *Options) error { return fmt.Errorf("failed to validate flags: %w", err) } if err := validateFlags(opts); err != nil { - return fmt.Errorf("failed to validate flags: %w", err) + return err } q, filter, err := buildQueryAndFilter(opts) if err != nil { - return fmt.Errorf("failed to validate flags: %w", err) + return err } src, err := newSource(opts) @@ -256,7 +256,7 @@ func runLog(opts *Options) error { return fmt.Errorf("failed to select log source: %w", err) } if opts.Replicas != "" && !src.Caps().Replicas { - return fmt.Errorf("failed to validate flags: --replica needs a replica-capable log source; the %q source does not provide replica information", src.Name()) + return fmt.Errorf("--replica needs a replica-capable log source; the %q source does not provide replica information", src.Name()) } // Instance resolution is bounded by the global deadline. diff --git a/vcr/instance/log/log_test.go b/vcr/instance/log/log_test.go index b940233..b1f8d0a 100644 --- a/vcr/instance/log/log_test.go +++ b/vcr/instance/log/log_test.go @@ -207,7 +207,7 @@ func TestLog(t *testing.T) { LogGetInstanceByIDTimes: 0, }, want: want{ - errMsg: `failed to validate flags: invalid --log-level "loud": want one of trace, debug, info, warn, error, fatal`, + errMsg: `invalid --log-level "loud": want one of trace, debug, info, warn, error, fatal`, }, }, { @@ -243,7 +243,7 @@ func TestLog(t *testing.T) { LogGetInstanceByIDTimes: 0, }, want: want{ - errMsg: `failed to validate flags: invalid --to value "not-a-time": expected RFC3339`, + errMsg: `invalid --to value "not-a-time": expected RFC3339`, }, }, { @@ -1000,7 +1000,8 @@ func Test_runLog_rejectsNonPositiveSizes(t *testing.T) { _, err := cmd.ExecuteC() require.Error(t, err) - require.Contains(t, err.Error(), "failed to validate flags: ") + require.NotContains(t, err.Error(), "failed to validate flags: ", + "self-describing flag errors must not be wrapped in a generic prefix") require.Contains(t, err.Error(), tt.want) }) }