diff --git a/docs/vcr.md b/docs/vcr.md index 9ccf35a..68f4a0f 100644 --- a/docs/vcr.md +++ b/docs/vcr.md @@ -5,17 +5,68 @@ 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 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 + ### 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 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" + ``` ### Options @@ -33,14 +84,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..5536109 100644 --- a/docs/vcr_instance_log.md +++ b/docs/vcr_instance_log.md @@ -1,52 +1,84 @@ ## 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, 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. + ``` -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 +95,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..dfab185 --- /dev/null +++ b/docs/vcr_logs.md @@ -0,0 +1,100 @@ +## 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, 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. + + +``` +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 diff --git a/pkg/logs/buffer.go b/pkg/logs/buffer.go new file mode 100644 index 0000000..35f1430 --- /dev/null +++ b/pkg/logs/buffer.go @@ -0,0 +1,60 @@ +package logs + +import "sync" + +// DefaultBufferSize is the number of entries retained in memory when the user +// does not override --buffer. +const DefaultBufferSize = 5000 + +// 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 + 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. 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 new file mode 100644 index 0000000..d80228c --- /dev/null +++ b/pkg/logs/buffer_test.go @@ -0,0 +1,85 @@ +package logs + +import ( + "sync" + "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) { + // 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"}) + b.Add(Entry{Message: "b"}) + + 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) { + require.Equal(t, DefaultBufferSize, NewBuffer(0).Cap()) + require.Equal(t, DefaultBufferSize, NewBuffer(-5).Cap()) +} diff --git a/pkg/logs/filter.go b/pkg/logs/filter.go new file mode 100644 index 0000000..b5310ef --- /dev/null +++ b/pkg/logs/filter.go @@ -0,0 +1,157 @@ +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 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 new file mode 100644 index 0000000..5f60766 --- /dev/null +++ b/pkg/logs/filter_test.go @@ -0,0 +1,76 @@ +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/") +} + +// 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 new file mode 100644 index 0000000..cec7cc8 --- /dev/null +++ b/pkg/logs/graphql_source.go @@ -0,0 +1,172 @@ +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 + +// 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 { + 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. +// +// 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 + onFollowError func(error) +} + +// NewGraphQLSource returns a source backed by the datastore. +func NewGraphQLSource(l LogLister, pollInterval time.Duration, opts ...GraphQLOption) *GraphQLSource { + if pollInterval <= 0 { + pollInterval = time.Second + } + s := &GraphQLSource{lister: l, pollInterval: pollInterval} + for _, o := range opts { + o(s) + } + return s +} + +// 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. 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 + } + limit := q.Limit + if limit <= 0 { + limit = FollowPageSize + } + rows, err := s.lister.ListLogsByInstanceID(ctx, q.InstanceID, limit, q.From) + if err != nil { + // 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)) + } + // 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 { + limit = FollowPageSize + } + cursor := q.From + ticker := time.NewTicker(s.pollInterval) + defer ticker.Stop() + + failures := 0 + for { + rows, err := s.lister.ListLogsByInstanceID(ctx, q.InstanceID, limit, cursor) + 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) + } + // 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) + } + 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 + } + + 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..4fba97c --- /dev/null +++ b/pkg/logs/graphql_source_test.go @@ -0,0 +1,455 @@ +package logs + +import ( + "context" + "errors" + "testing" + "time" + + "github.com/stretchr/testify/require" + + "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, 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 + } + if len(f.pages) == 0 { + return nil, nil + } + page := f.pages[0] + f.pages = f.pages[1:] + 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) + 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()) + 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]) + require.Equal(t, []string{"inst-1"}, lister.ids, "Query.InstanceID is passed through") +} + +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) +} + +// 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, "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) { + 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.WithTimeout(context.Background(), followTimeout) + defer cancel() + out := make(chan Entry, 8) + done := startFollow(ctx, s, Query{InstanceID: "inst-follow", Limit: 300}, out) + + require.Equal(t, "first", recvEntry(t, out).Message) + require.Equal(t, "second", recvEntry(t, out).Message) + cancel() + 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) { + 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.WithTimeout(context.Background(), followTimeout) + defer cancel() + out := make(chan Entry, 8) + // 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, recvEntry(t, out).Message) + } + cancel() + 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.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_FollowSurfacesAPersistentListerError(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 that never recovers must surface") + require.ErrorIs(t, err, sentinel) + 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, "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) { + 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") + }) + } +} diff --git a/pkg/logs/registry.go b/pkg/logs/registry.go new file mode 100644 index 0000000..88c2baa --- /dev/null +++ b/pkg/logs/registry.go @@ -0,0 +1,95 @@ +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. 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 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, +// 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). 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() + 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..e9f09e0 --- /dev/null +++ b/pkg/logs/registry_test.go @@ -0,0 +1,122 @@ +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_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() + + const writers = 8 + const perWriter = 50 + + var wg sync.WaitGroup + wg.Add(writers * 2) + for w := 0; w < writers; w++ { + go func() { + defer wg.Done() + for i := 0; i < perWriter; i++ { + r.Ensure(fmt.Sprintf("host-%d", i%4)) + } + }() + 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") + + // 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()) +} diff --git a/pkg/logs/render.go b/pkg/logs/render.go new file mode 100644 index 0000000..132ea5f --- /dev/null +++ b/pkg/logs/render.go @@ -0,0 +1,147 @@ +package logs + +import ( + "encoding/json" + "fmt" + "strings" + "time" + + "github.com/cli/cli/v2/pkg/iostreams" +) + +// 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 + // 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 human-format timestamps in UTC instead of local time. JSONLine + // is always UTC and ignores this flag. + UTC bool +} + +// Renderer formats entries for the terminal. +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. +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. It +// does not consult RenderOptions.JSON; a caller wanting JSON calls JSONLine. +func (r *Renderer) Line(e Entry) string { + out := r.at(e.Timestamp).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 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.UTC() + b, err := json.Marshal(out) + if err != nil { + return "", fmt.Errorf("failed to encode log entry: %w", err) + } + 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 { + padded := fmt.Sprintf("%-5s", level) + switch strings.ToLower(level) { + case "error", "fatal": + return r.cs.Red(padded) + case "warn": + return r.cs.Yellow(padded) + case "debug", "trace": + return r.cs.Muted(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 digits in the id 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 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 { + 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..a7c6c31 --- /dev/null +++ b/pkg/logs/render_test.go @@ -0,0 +1,270 @@ +package logs + +import ( + "encoding/json" + "regexp" + "strings" + "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) +} + +// 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{ + 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"`) +} + +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") +} + +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") +} + +// 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_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") + }) + } +} + +// 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) + + 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) { + 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)) +} diff --git a/pkg/logs/source.go b/pkg/logs/source.go new file mode 100644 index 0000000..983f999 --- /dev/null +++ b/pkg/logs/source.go @@ -0,0 +1,74 @@ +// 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 + // 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 +// 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 +} diff --git a/vcr/instance/log/log.go b/vcr/instance/log/log.go index b829a8b..dfc71e5 100644 --- a/vcr/instance/log/log.go +++ b/vcr/instance/log/log.go @@ -6,192 +6,412 @@ 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"}, "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, "vcr logs") +} + +// 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{ - 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, 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: 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 - - # 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 + Example: fmt.Sprintf(heredoc.Doc(` + # Print recent logs and exit + $ %[1]s --project-name my-app --instance-name dev - # Print the last 500 log entries and exit - $ vcr instance log -p my-app -n dev --history 500 + # Follow new logs (Ctrl+C to stop) + $ %[1]s -p my-app -n dev --follow - # Filter to show only errors and above - $ vcr instance log -p my-app -n dev --log-level error + # The last 15 minutes, errors only + $ %[1]s -p my-app -n dev --since 15m --log-level error - # Show only application logs (exclude provider logs) - $ vcr instance log -p my-app -n dev --source-type application + # An explicit window + $ %[1]s -i 12345678-1234-1234-1234-123456789abc --from 2026-08-02T10:00:00Z --to 2026-08-02T11:00:00Z - # 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 + $ %[1]s -p my-app -n dev --grep 'pay.*502' --exclude '/health' --json + `), invocation), 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 { +// 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) { + 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, flagPatternError("--grep", opts.Grep, err) + } + if err := f.SetExclude(opts.Exclude); err != nil { + 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, + 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) + } +} + +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) } + if err := validateFlags(opts); err != nil { + return err + } - inst, err := getInstance(ctx, opts) + q, filter, err := buildQueryAndFilter(opts) if err != nil { - return fmt.Errorf("failed to get instance: %w", err) + return 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("--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) +} + +// 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 log history: %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++ + } + 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 +} - ticker := time.NewTicker(TickerInterval) - defer ticker.Stop() - lastTimestamp := time.Time{} +// 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) }() + + // 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) + } + + // 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 <-ticker.C: - lastTimestamp = fetchLogs(io, opts, lastTimestamp) case <-interrupt: - fmt.Println("Interrupt received, stopping...") + // 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 + case err := <-errCh: + drain() + if err != nil { + return fmt.Errorf("failed to stream logs: %w", err) + } return nil + case e := <-entries: + show(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 +// 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 } - - for i := len(logs) - 1; i >= 0; i-- { - log := logs[i] - printLogs(out, opts, log) - lastTimestamp = log.Timestamp + if marker := renderer.DateMarker(e); marker != "" { + fmt.Fprintln(io.Out, marker) } - - return lastTimestamp + fmt.Fprintln(io.Out, renderer.Line(e)) } func getInstance(ctx context.Context, opts *Options) (api.Instance, error) { @@ -214,30 +434,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..b1f8d0a 100644 --- a/vcr/instance/log/log_test.go +++ b/vcr/instance/log/log_test.go @@ -2,9 +2,14 @@ package log import ( "bytes" + "context" "errors" + "fmt" "io" "os" + "os/signal" + "strings" + "sync" "testing" "time" @@ -14,10 +19,100 @@ 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("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) + 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 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 @@ -87,7 +182,79 @@ 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: `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", + }, + }, + { + name: "malformed-to-fails-closed", + cli: "--id=abc-123 --to=not-a-time", + mock: mock{ + LogListLogsByInstanceIDTimes: 0, + LogGetInstanceByIDTimes: 0, + }, + want: want{ + errMsg: `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`, }, }, { @@ -167,178 +334,977 @@ 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 +func TestLog_Follow(t *testing.T) { + ctrl := gomock.NewController(t) + + datastoreMock := mocks.NewMockDatastoreInterface(ctrl) + deploymentMock := mocks.NewMockDeploymentInterface(ctrl) + + datastoreMock.EXPECT(). + GetInstanceByID(gomock.Any(), "abc-123"). + Times(1). + Return(api.Instance{ID: "abc-123"}, nil) + + // Track how many times ListLogsByInstanceID is called and send SIGTERM + // after the second tick so the follow loop exits cleanly. + callCount := 0 + datastoreMock.EXPECT(). + ListLogsByInstanceID(gomock.Any(), gomock.Any(), gomock.Any(), gomock.Any()). + MinTimes(2). + DoAndReturn(func(_ interface{}, _ interface{}, _ interface{}, _ interface{}) ([]api.Log, error) { + callCount++ + if callCount >= 2 { + // Send an interrupt to the current process so runLog's signal + // handler fires and the follow loop exits. + p, _ := os.FindProcess(os.Getpid()) + _ = p.Signal(os.Interrupt) + } + return []api.Log{{Timestamp: time.Now(), SourceType: "application", Message: "streaming"}}, nil + }) + + ios, _, stdout, _ := iostreams.Test() + + argv, err := shlex.Split("--id=abc-123 --follow") + require.NoError(t, err) + + f := testutil.DefaultFactoryMock(t, ios, nil, nil, datastoreMock, deploymentMock, nil, nil) + + cmd := NewCmdInstanceLog(f) + cmd.SetArgs(argv) + cmd.SetIn(&bytes.Buffer{}) + cmd.SetOut(io.Discard) + cmd.SetErr(io.Discard) + + _, 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(), "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 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" } +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, out chan<- logs.Entry) error { + _, s.hadDeadline = ctx.Deadline() + for _, e := range s.emit { + select { + case out <- e: + case <-ctx.Done(): + return nil + } } - 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"}, - }, + 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 } +} - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { +// 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} - ctrl := gomock.NewController(t) + src := &fakeFollowSource{} + err := runFollowWithTimeout(t, src, opts, &logs.Filter{}, + logs.NewRenderer(ios.ColorScheme(), logs.RenderOptions{})) - 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) + require.NoError(t, err) + require.False(t, src.hadDeadline, "follow context must not carry the global --timeout deadline") +} - ios, _, stdout, stderr := iostreams.Test() - lastTimestamp := time.Now() +// 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} - f := testutil.DefaultFactoryMock(t, ios, nil, nil, datastoreMock, nil, nil, nil) + src := &fakeFollowSource{followErr: errors.New("transport died")} + err := runFollowWithTimeout(t, src, opts, &logs.Filter{}, + logs.NewRenderer(ios.ColorScheme(), logs.RenderOptions{})) - opts := &Options{ - Factory: f, - } + require.Error(t, err) + require.Contains(t, err.Error(), "failed to stream logs: transport died") +} - fetchLogs(ios, opts, lastTimestamp) +// 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) - cmdOut := &testutil.CmdOut{ - OutBuf: stdout, - ErrBuf: stderr, - } - if tt.want.stderr != "" { - require.Equal(t, tt.want.stderr, cmdOut.Stderr()) - return + 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 } - require.Equal(t, tt.want.stdout, cmdOut.String()) }) + + 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) { + 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")) + }) } -func Test_printLogs(t *testing.T) { +// 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} - type mock struct { - LogSourceType string - LogLogLevel string + 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), + }) } - type want struct { - stdout string + 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") } - 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: ""}, - }, +} + +// 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), + }) } - for _, tt := range tests { - t.Run(tt.name, func(t *testing.T) { + err := runFollowWithTimeout(t, &fakeFollowSource{emit: emit}, opts, &logs.Filter{}, + logs.NewRenderer(ios.ColorScheme(), logs.RenderOptions{})) - ios, _, stdout, _ := iostreams.Test() + 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") + } +} - opts := &Options{ - SourceType: tt.mock.LogSourceType, - LogLevel: tt.mock.LogLogLevel, - } +// 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 } - printLogs(ios, opts, api.Log{Timestamp: time.Now(), SourceType: "application", Message: "test", LogLevel: "info"}) +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 +} - require.Equal(t, tt.want.stdout, stdout.String()) +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") + } } -func TestLog_Follow(t *testing.T) { +// 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) - deploymentMock := mocks.NewMockDeploymentInterface(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")) - // Track how many times ListLogsByInstanceID is called and send SIGTERM - // after the second tick so the follow loop exits cleanly. - callCount := 0 + 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.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") +} + +// 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()). - MinTimes(2). - DoAndReturn(func(_ interface{}, _ interface{}, _ interface{}, _ interface{}) ([]api.Log, error) { - callCount++ - if callCount >= 2 { - // Send an interrupt to the current process so runLog's signal - // handler fires and the follow loop exits. - p, _ := os.FindProcess(os.Getpid()) - _ = p.Signal(os.Interrupt) - } - return []api.Log{{Timestamp: time.Now(), SourceType: "application", Message: "streaming"}}, nil - }) + 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) - argv, err := shlex.Split("--id=abc-123 --follow") + 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) - f := testutil.DefaultFactoryMock(t, ios, nil, nil, datastoreMock, deploymentMock, nil, nil) + out := stdout.String() + 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")) + 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, "%!") +} + +// 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.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) + }) + } +} + +// 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(argv) + 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, "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") + _, 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") } diff --git a/vcr/root/root.go b/vcr/root/root.go index 4289eb9..cae49f9 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" ) @@ -59,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 @@ -86,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" @@ -165,6 +170,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)") @@ -180,6 +190,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 diff --git a/vcr/root/root_test.go b/vcr/root/root_test.go index 81253ad..59ca7aa 100644 --- a/vcr/root/root_test.go +++ b/vcr/root/root_test.go @@ -84,3 +84,39 @@ 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) +} + +// 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") +}