diff --git a/cmd/goose/cache.go b/cmd/goose/cache.go index a7f1b3a..641eb72 100644 --- a/cmd/goose/cache.go +++ b/cmd/goose/cache.go @@ -35,6 +35,13 @@ func (app *App) turnData(ctx context.Context, url string, updatedAt time.Time) ( hash := sha256.Sum256([]byte(key)) cacheFile := filepath.Join(app.cacheDir, hex.EncodeToString(hash[:])[:16]+".json") + // Log the cache key details + slog.Debug("[CACHE] Checking cache", + "url", url, + "updated_at", updatedAt.Format(time.RFC3339), + "cache_key", key, + "cache_file", filepath.Base(cacheFile)) + // Skip cache if --no-cache flag is set if !app.noCache { // Try to read from cache (gracefully handle all cache errors) @@ -47,9 +54,33 @@ func (app *App) turnData(ctx context.Context, url string, updatedAt time.Time) ( slog.Error("Failed to remove corrupted cache file", "error", removeErr) } } else if time.Since(entry.CachedAt) < cacheTTL && entry.UpdatedAt.Equal(updatedAt) { - // Check if cache is still valid (2 hour TTL) + // Check if cache is still valid (10 day TTL, but PR UpdatedAt is primary check) + slog.Debug("[CACHE] Cache hit", + "url", url, + "cached_at", entry.CachedAt.Format(time.RFC3339), + "cache_age", time.Since(entry.CachedAt).Round(time.Second), + "pr_updated_at", entry.UpdatedAt.Format(time.RFC3339)) + if app.healthMonitor != nil { + app.healthMonitor.recordCacheAccess(true) + } return entry.Data, true, nil + } else { + // Log why cache was invalid + if !entry.UpdatedAt.Equal(updatedAt) { + slog.Debug("[CACHE] Cache miss - PR updated", + "url", url, + "cached_pr_time", entry.UpdatedAt.Format(time.RFC3339), + "current_pr_time", updatedAt.Format(time.RFC3339)) + } else if time.Since(entry.CachedAt) >= cacheTTL { + slog.Debug("[CACHE] Cache miss - TTL expired", + "url", url, + "cached_at", entry.CachedAt.Format(time.RFC3339), + "cache_age", time.Since(entry.CachedAt).Round(time.Second), + "ttl", cacheTTL) + } } + } else if !os.IsNotExist(readErr) { + slog.Debug("[CACHE] Cache file read error", "url", url, "error", readErr) } } @@ -57,7 +88,12 @@ func (app *App) turnData(ctx context.Context, url string, updatedAt time.Time) ( if app.noCache { slog.Debug("Cache bypassed (--no-cache), fetching from Turn API", "url", url) } else { - slog.Debug("Cache miss, fetching from Turn API", "url", url) + slog.Info("[CACHE] Cache miss, fetching from Turn API", + "url", url, + "pr_updated_at", updatedAt.Format(time.RFC3339)) + if app.healthMonitor != nil { + app.healthMonitor.recordCacheAccess(false) + } } // Use exponential backoff with jitter for Turn API calls @@ -68,11 +104,16 @@ func (app *App) turnData(ctx context.Context, url string, updatedAt time.Time) ( defer cancel() var retryErr error + slog.Debug("[TURN] Making API call", + "url", url, + "user", app.currentUser.GetLogin(), + "pr_updated_at", updatedAt.Format(time.RFC3339)) data, retryErr = app.turnClient.Check(turnCtx, url, app.currentUser.GetLogin(), updatedAt) if retryErr != nil { slog.Warn("Turn API error (will retry)", "error", retryErr) return retryErr } + slog.Debug("[TURN] API call successful", "url", url) return nil }, retry.Attempts(maxRetries), @@ -85,9 +126,16 @@ func (app *App) turnData(ctx context.Context, url string, updatedAt time.Time) ( ) if err != nil { slog.Error("Turn API error after retries (will use PR without metadata)", "maxRetries", maxRetries, "error", err) + if app.healthMonitor != nil { + app.healthMonitor.recordAPICall(false) + } return nil, false, err } + if app.healthMonitor != nil { + app.healthMonitor.recordAPICall(true) + } + // Save to cache (don't fail if caching fails) - skip if --no-cache is set if !app.noCache { entry := cacheEntry{ @@ -103,6 +151,12 @@ func (app *App) turnData(ctx context.Context, url string, updatedAt time.Time) ( slog.Error("Failed to create cache directory", "error", dirErr) } else if writeErr := os.WriteFile(cacheFile, cacheData, 0o600); writeErr != nil { slog.Error("Failed to write cache file", "error", writeErr) + } else { + slog.Debug("[CACHE] Saved to cache", + "url", url, + "cached_at", entry.CachedAt.Format(time.RFC3339), + "pr_updated_at", entry.UpdatedAt.Format(time.RFC3339), + "cache_file", filepath.Base(cacheFile)) } } } @@ -110,7 +164,7 @@ func (app *App) turnData(ctx context.Context, url string, updatedAt time.Time) ( return data, false, nil } -// cleanupOldCache removes cache files older than 5 days. +// cleanupOldCache removes cache files older than the cleanup interval (15 days). func (app *App) cleanupOldCache() { entries, err := os.ReadDir(app.cacheDir) if err != nil { @@ -131,7 +185,7 @@ func (app *App) cleanupOldCache() { continue } - // Remove cache files older than 5 days + // Remove cache files older than cleanup interval (15 days) if time.Since(info.ModTime()) > cacheCleanupInterval { filePath := filepath.Join(app.cacheDir, entry.Name()) if removeErr := os.Remove(filePath); removeErr != nil { diff --git a/cmd/goose/deadlock_test.go b/cmd/goose/deadlock_test.go index 58f29ee..7bd1fd8 100644 --- a/cmd/goose/deadlock_test.go +++ b/cmd/goose/deadlock_test.go @@ -14,7 +14,7 @@ func TestConcurrentMenuOperations(t *testing.T) { hiddenOrgs: make(map[string]bool), seenOrgs: make(map[string]bool), blockedPRTimes: make(map[string]time.Time), - browserRateLimiter: NewBrowserRateLimiter(30*time.Second, 5, defaultMaxBrowserOpensDay), + browserRateLimiter: NewBrowserRateLimiter(startupGracePeriod, 5, defaultMaxBrowserOpensDay), systrayInterface: &MockSystray{}, incoming: []PR{ {Repository: "org1/repo1", Number: 1, Title: "Fix bug", URL: "https://github.com/org1/repo1/pull/1"}, @@ -101,7 +101,7 @@ func TestMenuClickDeadlockScenario(t *testing.T) { hiddenOrgs: make(map[string]bool), seenOrgs: make(map[string]bool), blockedPRTimes: make(map[string]time.Time), - browserRateLimiter: NewBrowserRateLimiter(30*time.Second, 5, defaultMaxBrowserOpensDay), + browserRateLimiter: NewBrowserRateLimiter(startupGracePeriod, 5, defaultMaxBrowserOpensDay), systrayInterface: &MockSystray{}, incoming: []PR{ {Repository: "org1/repo1", Number: 1, Title: "Test PR", URL: "https://github.com/org1/repo1/pull/1"}, @@ -142,7 +142,7 @@ func TestRapidMenuClicks(t *testing.T) { hiddenOrgs: make(map[string]bool), seenOrgs: make(map[string]bool), blockedPRTimes: make(map[string]time.Time), - browserRateLimiter: NewBrowserRateLimiter(30*time.Second, 5, defaultMaxBrowserOpensDay), + browserRateLimiter: NewBrowserRateLimiter(startupGracePeriod, 5, defaultMaxBrowserOpensDay), systrayInterface: &MockSystray{}, lastSearchAttempt: time.Now().Add(-15 * time.Second), // Allow first click incoming: []PR{ diff --git a/cmd/goose/github.go b/cmd/goose/github.go index 983aafc..9e262f0 100644 --- a/cmd/goose/github.go +++ b/cmd/goose/github.go @@ -22,11 +22,14 @@ import ( // extractOrgFromRepo extracts the organization name from a repository path like "org/repo". func extractOrgFromRepo(repo string) string { - parts := strings.Split(repo, "/") - if len(parts) >= 1 { - return parts[0] + idx := strings.Index(repo, "/") + if idx > 0 { + return repo[:idx] } - return "" + if idx == 0 { + return "" // Invalid: starts with "/" + } + return repo // No slash: return as-is (single segment or empty) } // initClients initializes GitHub and Turn API clients. @@ -180,25 +183,42 @@ func (app *App) executeGitHubQuery(ctx context.Context, query string, opts *gith var result *github.IssuesSearchResult var resp *github.Response - err := retry.Do(func() error { + // Use circuit breaker if available + if app.githubCircuit != nil { + err := app.githubCircuit.call(func() error { + return app.executeGitHubQueryInternal(ctx, query, opts, &result, &resp) + }) + if err != nil { + return nil, err + } + return result, nil + } + + // Fallback to direct execution + err := app.executeGitHubQueryInternal(ctx, query, opts, &result, &resp) + return result, err +} + +func (app *App) executeGitHubQueryInternal(ctx context.Context, query string, opts *github.SearchOptions, result **github.IssuesSearchResult, resp **github.Response) error { + return retry.Do(func() error { // Create timeout context for GitHub API call githubCtx, cancel := context.WithTimeout(ctx, 30*time.Second) defer cancel() var retryErr error - result, resp, retryErr = app.client.Search.Issues(githubCtx, query, opts) + *result, *resp, retryErr = app.client.Search.Issues(githubCtx, query, opts) if retryErr != nil { // Enhanced error handling with specific cases - if resp != nil { + if *resp != nil { const ( httpStatusUnauthorized = 401 httpStatusForbidden = 403 httpStatusUnprocessable = 422 ) - switch resp.StatusCode { + switch (*resp).StatusCode { case httpStatusForbidden: - if resp.Header.Get("X-Ratelimit-Remaining") == "0" { - resetTime := resp.Header.Get("X-Ratelimit-Reset") + if (*resp).Header.Get("X-Ratelimit-Remaining") == "0" { + resetTime := (*resp).Header.Get("X-Ratelimit-Reset") slog.Warn("GitHub API rate limited (will retry)", "resetTime", resetTime) return retryErr // Retry on rate limit } @@ -211,7 +231,7 @@ func (app *App) executeGitHubQuery(ctx context.Context, query string, opts *gith slog.Error("GitHub API query invalid", "query", query) return retry.Unrecoverable(fmt.Errorf("github API query invalid: %w", retryErr)) default: - slog.Warn("GitHub API error (will retry)", "statusCode", resp.StatusCode, "error", retryErr) + slog.Warn("GitHub API error (will retry)", "statusCode", (*resp).StatusCode, "error", retryErr) } } else { // Likely network error - retry these @@ -229,10 +249,6 @@ func (app *App) executeGitHubQuery(ctx context.Context, query string, opts *gith }), retry.Context(ctx), ) - if err != nil { - return nil, err - } - return result, nil } // prResult holds the result of a Turn API query for a PR. @@ -371,8 +387,10 @@ func (app *App) fetchPRsInternal(ctx context.Context) (incoming []PR, outgoing [ Title: issue.GetTitle(), URL: issue.GetHTMLURL(), Repository: repo, + Author: issue.GetUser().GetLogin(), Number: issue.GetNumber(), UpdatedAt: issue.GetUpdatedAt().Time, + IsDraft: issue.GetDraft(), } // Categorize as incoming or outgoing @@ -477,22 +495,24 @@ func (app *App) fetchTurnDataSync(ctx context.Context, issues []*github.Issue, u // Update the PR in the slices directly if result.isOwner { for i := range *outgoing { - if (*outgoing)[i].URL == result.url { - (*outgoing)[i].NeedsReview = needsReview - (*outgoing)[i].IsBlocked = isBlocked - (*outgoing)[i].ActionReason = actionReason - (*outgoing)[i].ActionKind = actionKind - break + if (*outgoing)[i].URL != result.url { + continue } + (*outgoing)[i].NeedsReview = needsReview + (*outgoing)[i].IsBlocked = isBlocked + (*outgoing)[i].ActionReason = actionReason + (*outgoing)[i].ActionKind = actionKind + break } } else { for i := range *incoming { - if (*incoming)[i].URL == result.url { - (*incoming)[i].NeedsReview = needsReview - (*incoming)[i].ActionReason = actionReason - (*incoming)[i].ActionKind = actionKind - break + if (*incoming)[i].URL != result.url { + continue } + (*incoming)[i].NeedsReview = needsReview + (*incoming)[i].ActionReason = actionReason + (*incoming)[i].ActionKind = actionKind + break } } } else if result.err != nil { diff --git a/cmd/goose/main.go b/cmd/goose/main.go index e7ec3d9..ebff0ff 100644 --- a/cmd/goose/main.go +++ b/cmd/goose/main.go @@ -30,8 +30,8 @@ var ( ) const ( - cacheTTL = 2 * time.Hour - cacheCleanupInterval = 5 * 24 * time.Hour + cacheTTL = 10 * 24 * time.Hour // 10 days - rely mostly on PR UpdatedAt + cacheCleanupInterval = 15 * 24 * time.Hour // 15 days - cleanup older than cache TTL stalePRThreshold = 90 * 24 * time.Hour maxPRsToProcess = 200 minUpdateInterval = 10 * time.Second @@ -45,7 +45,7 @@ const ( turnAPITimeout = 10 * time.Second maxConcurrentTurnAPICalls = 20 defaultMaxBrowserOpensDay = 20 - startupGracePeriod = 30 * time.Second // Don't play sounds or auto-open for first 30 seconds + startupGracePeriod = 1 * time.Minute // Don't play sounds or auto-open for first minute ) // PR represents a pull request with metadata. @@ -56,9 +56,11 @@ type PR struct { Title string URL string Repository string + Author string // GitHub username of the PR author ActionReason string ActionKind string // The kind of action expected (review, merge, fix_tests, etc.) Number int + IsDraft bool IsBlocked bool NeedsReview bool } @@ -90,68 +92,27 @@ type App struct { mu sync.RWMutex enableAutoBrowser bool hideStaleIncoming bool + hasPerformedInitialDiscovery bool // Track if we've done the first poll to distinguish from real state changes noCache bool enableAudioCues bool initialLoadComplete bool menuInitialized bool -} - -func loadCurrentUser(ctx context.Context, app *App) { - slog.Info("Loading current user...") - - if app.client == nil { - slog.Info("Skipping user load - no GitHub client available") - return - } - - var user *github.User - err := retry.Do(func() error { - var retryErr error - user, _, retryErr = app.client.Users.Get(ctx, "") - if retryErr != nil { - slog.Warn("GitHub Users.Get failed (will retry)", "error", retryErr) - return retryErr - } - return nil - }, - retry.Attempts(maxRetries), - retry.DelayType(retry.CombineDelay(retry.BackOffDelay, retry.RandomDelay)), // Add jitter for better backoff distribution - retry.MaxDelay(maxRetryDelay), - retry.OnRetry(func(n uint, err error) { - slog.Warn("[GITHUB] Users.Get retry", "attempt", n+1, "maxRetries", maxRetries, "error", err) - }), - retry.Context(ctx), - ) - if err != nil { - slog.Warn("Failed to load current user after retries", "maxRetries", maxRetries, "error", err) - if app.authError == "" { - app.authError = fmt.Sprintf("Failed to load user: %v", err) - } - return - } - - if user == nil { - slog.Warn("GitHub API returned nil user") - return - } - - app.currentUser = user - // Log if we're using a different target user (sanitized) - if app.targetUser != "" && app.targetUser != user.GetLogin() { - slog.Info("Querying PRs for different user", "targetUser", sanitizeForLog(app.targetUser)) - } + healthMonitor *healthMonitor + githubCircuit *circuitBreaker } func main() { // Parse command line flags var targetUser string var noCache bool + var debugMode bool var updateInterval time.Duration var browserOpenDelay time.Duration var maxBrowserOpensMinute int var maxBrowserOpensDay int flag.StringVar(&targetUser, "user", "", "GitHub user to query PRs for (defaults to authenticated user)") flag.BoolVar(&noCache, "no-cache", false, "Bypass cache for debugging") + flag.BoolVar(&debugMode, "debug", false, "Enable debug logging") flag.DurationVar(&updateInterval, "interval", defaultUpdateInterval, "Update interval (e.g. 30s, 1m, 5m)") flag.DurationVar(&browserOpenDelay, "browser-delay", 1*time.Minute, "Minimum delay before opening PRs in browser after startup") flag.IntVar(&maxBrowserOpensMinute, "browser-max-per-minute", 2, "Maximum browser windows to open per minute") @@ -187,9 +148,13 @@ func main() { } // Set up structured logging with source location + logLevel := slog.LevelInfo + if debugMode { + logLevel = slog.LevelDebug + } opts := &slog.HandlerOptions{ AddSource: true, - Level: slog.LevelInfo, + Level: logLevel, } slog.SetDefault(slog.New(slog.NewTextHandler(os.Stderr, opts))) slog.Info("Starting GitHub PR Monitor", "version", version, "commit", commit, "date", date) @@ -252,6 +217,8 @@ func main() { // Deprecated fields for test compatibility previousBlockedPRs: make(map[string]bool), blockedPRTimes: make(map[string]time.Time), + healthMonitor: newHealthMonitor(), + githubCircuit: newCircuitBreaker("github", 5, 2*time.Minute), } // Load saved settings @@ -266,7 +233,43 @@ func main() { } // Load current user if we have a client - loadCurrentUser(ctx, app) + slog.Info("Loading current user...") + if app.client != nil { + var user *github.User + err := retry.Do(func() error { + var retryErr error + user, _, retryErr = app.client.Users.Get(ctx, "") + if retryErr != nil { + slog.Warn("GitHub Users.Get failed (will retry)", "error", retryErr) + return retryErr + } + return nil + }, + retry.Attempts(maxRetries), + retry.DelayType(retry.CombineDelay(retry.BackOffDelay, retry.RandomDelay)), // Add jitter for better backoff distribution + retry.MaxDelay(maxRetryDelay), + retry.OnRetry(func(n uint, err error) { + slog.Warn("[GITHUB] Users.Get retry", "attempt", n+1, "maxRetries", maxRetries, "error", err) + }), + retry.Context(ctx), + ) + if err != nil { + slog.Warn("Failed to load current user after retries", "maxRetries", maxRetries, "error", err) + if app.authError == "" { + app.authError = fmt.Sprintf("Failed to load user: %v", err) + } + } else if user != nil { + app.currentUser = user + // Log if we're using a different target user (sanitized) + if app.targetUser != "" && app.targetUser != user.GetLogin() { + slog.Info("Querying PRs for different user", "targetUser", sanitizeForLog(app.targetUser)) + } + } else { + slog.Warn("GitHub API returned nil user") + } + } else { + slog.Info("Skipping user load - no GitHub client available") + } slog.Info("Starting systray...") // Create a cancellable context for the application @@ -368,6 +371,11 @@ func (app *App) updateLoop(ctx context.Context) { ticker := time.NewTicker(app.updateInterval) defer ticker.Stop() + + // Health monitoring ticker - log metrics every 5 minutes + healthTicker := time.NewTicker(5 * time.Minute) + defer healthTicker.Stop() + slog.Info("[UPDATE] Update loop started", "interval", app.updateInterval) // Initial update with wait for Turn data @@ -375,6 +383,11 @@ func (app *App) updateLoop(ctx context.Context) { for { select { + case <-healthTicker.C: + // Log health metrics periodically + if app.healthMonitor != nil { + app.healthMonitor.logMetrics() + } case <-ticker.C: // Check if we should skip this scheduled update due to recent forced refresh app.mu.RLock() @@ -396,7 +409,12 @@ func (app *App) updateLoop(ctx context.Context) { } func (app *App) updatePRs(ctx context.Context) { - incoming, outgoing, err := app.fetchPRsInternal(ctx) + var incoming, outgoing []PR + err := safeExecute("fetchPRs", func() error { + var fetchErr error + incoming, outgoing, fetchErr = app.fetchPRsInternal(ctx) + return fetchErr + }) if err != nil { slog.Error("Error fetching PRs", "error", err) app.mu.Lock() @@ -501,6 +519,21 @@ func (app *App) updatePRs(ctx context.Context) { app.incoming = incoming app.outgoing = outgoing + slog.Info("[UPDATE] PR counts after update", + "incoming_count", len(incoming), + "outgoing_count", len(outgoing)) + // Log ALL outgoing PRs for debugging + slog.Debug("[UPDATE] Listing ALL outgoing PRs for debugging") + for i, pr := range outgoing { + slog.Debug("[UPDATE] Outgoing PR details", + "index", i, + "repo", pr.Repository, + "number", pr.Number, + "blocked", pr.IsBlocked, + "updated_at", pr.UpdatedAt.Format(time.RFC3339), + "title", pr.Title, + "url", pr.URL) + } // Mark initial load as complete after first successful update if !app.initialLoadComplete { app.initialLoadComplete = true @@ -517,6 +550,7 @@ func (app *App) updatePRs(ctx context.Context) { // updateMenu rebuilds the menu only if there are changes to improve UX. func (app *App) updateMenu(ctx context.Context) { + slog.Debug("[MENU] updateMenu called, generating current titles") // Generate current menu titles currentTitles := app.generateMenuTitles() @@ -533,6 +567,21 @@ func (app *App) updateMenu(ctx context.Context) { // Titles have changed, rebuild menu slog.Info("[MENU] Changes detected, rebuilding menu", "oldCount", len(lastTitles), "newCount", len(currentTitles)) + + // Log what changed for debugging + for i, current := range currentTitles { + if i < len(lastTitles) { + if current != lastTitles[i] { + slog.Debug("[MENU] Title changed", "index", i, "old", lastTitles[i], "new", current) + } + } else { + slog.Debug("[MENU] New title added", "index", i, "title", current) + } + } + for i := len(currentTitles); i < len(lastTitles); i++ { + slog.Debug("[MENU] Title removed", "index", i, "title", lastTitles[i]) + } + app.rebuildMenu(ctx) // Store new titles @@ -636,6 +685,7 @@ func (app *App) updatePRsWithWait(ctx context.Context) { if !app.menuInitialized { // Create initial menu with Turn data // Initialize menu structure + slog.Info("[FLOW] Creating initial menu (first time)") app.rebuildMenu(ctx) app.menuInitialized = true // Store initial menu titles to prevent unnecessary rebuild on first update @@ -645,14 +695,17 @@ func (app *App) updatePRsWithWait(ctx context.Context) { app.lastMenuTitles = menuTitles app.mu.Unlock() // Menu initialization complete + slog.Info("[FLOW] Initial menu created successfully") } else { + slog.Info("[FLOW] Updating existing menu") app.updateMenu(ctx) + slog.Info("[FLOW] Menu update completed") } // Process notifications using the simplified state manager - slog.Debug("[DEBUG] Processing PR state updates and notifications") + slog.Info("[FLOW] About to process PR state updates and notifications") app.updatePRStatesAndNotify(ctx) - slog.Debug("[DEBUG] Completed PR state updates and notifications") + slog.Info("[FLOW] Completed PR state updates and notifications") // Mark initial load as complete after first successful update if !app.initialLoadComplete { app.mu.Lock() @@ -667,6 +720,17 @@ func (app *App) tryAutoOpenPR(ctx context.Context, pr PR, autoBrowserEnabled boo return } + // Skip draft PRs authored by the user we're querying for + queriedUser := app.targetUser + if queriedUser == "" && app.currentUser != nil { + queriedUser = app.currentUser.GetLogin() + } + if pr.IsDraft && pr.Author == queriedUser { + slog.Debug("[BROWSER] Skipping auto-open for draft PR by queried user", + "repo", pr.Repository, "number", pr.Number, "author", pr.Author) + return + } + if app.browserRateLimiter.CanOpen(startTime, pr.URL) { slog.Info("[BROWSER] Auto-opening newly blocked PR", "repo", pr.Repository, "number", pr.Number, "url", pr.URL) diff --git a/cmd/goose/main_test.go b/cmd/goose/main_test.go index 6a487ac..04d332d 100644 --- a/cmd/goose/main_test.go +++ b/cmd/goose/main_test.go @@ -70,7 +70,7 @@ func TestMenuItemTitleTransition(t *testing.T) { hiddenOrgs: make(map[string]bool), seenOrgs: make(map[string]bool), blockedPRTimes: make(map[string]time.Time), - browserRateLimiter: NewBrowserRateLimiter(30*time.Second, 5, defaultMaxBrowserOpensDay), + browserRateLimiter: NewBrowserRateLimiter(startupGracePeriod, 5, defaultMaxBrowserOpensDay), systrayInterface: &MockSystray{}, // Use mock systray to avoid panics } @@ -185,7 +185,7 @@ func TestTrayIconRestoredAfterNetworkRecovery(t *testing.T) { blockedPRTimes: make(map[string]time.Time), hiddenOrgs: make(map[string]bool), seenOrgs: make(map[string]bool), - browserRateLimiter: NewBrowserRateLimiter(30*time.Second, 5, defaultMaxBrowserOpensDay), + browserRateLimiter: NewBrowserRateLimiter(startupGracePeriod, 5, defaultMaxBrowserOpensDay), systrayInterface: mock, menuInitialized: true, } @@ -226,7 +226,7 @@ func TestTrayTitleUpdates(t *testing.T) { blockedPRTimes: make(map[string]time.Time), hiddenOrgs: make(map[string]bool), seenOrgs: make(map[string]bool), - browserRateLimiter: NewBrowserRateLimiter(30*time.Second, 5, defaultMaxBrowserOpensDay), + browserRateLimiter: NewBrowserRateLimiter(startupGracePeriod, 5, defaultMaxBrowserOpensDay), systrayInterface: &MockSystray{}, // Use mock systray to avoid panics } @@ -349,7 +349,7 @@ func TestSoundPlaybackDuringTransitions(t *testing.T) { hiddenOrgs: make(map[string]bool), seenOrgs: make(map[string]bool), previousBlockedPRs: make(map[string]bool), - browserRateLimiter: NewBrowserRateLimiter(30*time.Second, 5, defaultMaxBrowserOpensDay), + browserRateLimiter: NewBrowserRateLimiter(startupGracePeriod, 5, defaultMaxBrowserOpensDay), enableAudioCues: true, initialLoadComplete: true, // Set to true to allow sound playback menuInitialized: true, @@ -494,7 +494,7 @@ func TestSoundDisabledNoPlayback(t *testing.T) { hiddenOrgs: make(map[string]bool), seenOrgs: make(map[string]bool), previousBlockedPRs: make(map[string]bool), - browserRateLimiter: NewBrowserRateLimiter(30*time.Second, 5, defaultMaxBrowserOpensDay), + browserRateLimiter: NewBrowserRateLimiter(startupGracePeriod, 5, defaultMaxBrowserOpensDay), enableAudioCues: false, // Audio disabled initialLoadComplete: true, menuInitialized: true, @@ -534,7 +534,7 @@ func TestGracePeriodPreventsNotifications(t *testing.T) { hiddenOrgs: make(map[string]bool), seenOrgs: make(map[string]bool), previousBlockedPRs: make(map[string]bool), - browserRateLimiter: NewBrowserRateLimiter(30*time.Second, 5, defaultMaxBrowserOpensDay), + browserRateLimiter: NewBrowserRateLimiter(startupGracePeriod, 5, defaultMaxBrowserOpensDay), enableAudioCues: true, initialLoadComplete: true, menuInitialized: true, @@ -569,8 +569,8 @@ func TestGracePeriodPreventsNotifications(t *testing.T) { t.Errorf("Expected PR to be tracked as blocked during grace period") } - // Now simulate time passing beyond grace period - app.startTime = time.Now().Add(-31 * time.Second) + // Now simulate time passing beyond grace period (1 minute) + app.startTime = time.Now().Add(-61 * time.Second) // New PR becomes blocked after grace period app.incoming = []PR{ @@ -659,7 +659,7 @@ func TestNotificationScenarios(t *testing.T) { hiddenOrgs: make(map[string]bool), seenOrgs: make(map[string]bool), previousBlockedPRs: make(map[string]bool), - browserRateLimiter: NewBrowserRateLimiter(30*time.Second, 5, defaultMaxBrowserOpensDay), + browserRateLimiter: NewBrowserRateLimiter(startupGracePeriod, 5, defaultMaxBrowserOpensDay), enableAudioCues: true, initialLoadComplete: tt.initialLoadComplete, menuInitialized: true, @@ -719,7 +719,7 @@ func TestNewlyBlockedPRAfterGracePeriod(t *testing.T) { hiddenOrgs: make(map[string]bool), seenOrgs: make(map[string]bool), previousBlockedPRs: make(map[string]bool), - browserRateLimiter: NewBrowserRateLimiter(30*time.Second, 5, defaultMaxBrowserOpensDay), + browserRateLimiter: NewBrowserRateLimiter(startupGracePeriod, 5, defaultMaxBrowserOpensDay), enableAudioCues: true, initialLoadComplete: true, // Already past initial load menuInitialized: true, diff --git a/cmd/goose/menu_change_detection_test.go b/cmd/goose/menu_change_detection_test.go index f87780b..1ec52f5 100644 --- a/cmd/goose/menu_change_detection_test.go +++ b/cmd/goose/menu_change_detection_test.go @@ -17,7 +17,7 @@ func TestMenuChangeDetection(t *testing.T) { hiddenOrgs: make(map[string]bool), seenOrgs: make(map[string]bool), blockedPRTimes: make(map[string]time.Time), - browserRateLimiter: NewBrowserRateLimiter(30*time.Second, 5, defaultMaxBrowserOpensDay), + browserRateLimiter: NewBrowserRateLimiter(startupGracePeriod, 5, defaultMaxBrowserOpensDay), systrayInterface: &MockSystray{}, incoming: []PR{ {Repository: "org1/repo1", Number: 1, Title: "Fix bug", URL: "https://github.com/org1/repo1/pull/1", NeedsReview: true, UpdatedAt: time.Now()}, @@ -110,7 +110,7 @@ func TestFirstRunMenuRebuildBug(t *testing.T) { hiddenOrgs: make(map[string]bool), seenOrgs: make(map[string]bool), blockedPRTimes: make(map[string]time.Time), - browserRateLimiter: NewBrowserRateLimiter(30*time.Second, 5, defaultMaxBrowserOpensDay), + browserRateLimiter: NewBrowserRateLimiter(startupGracePeriod, 5, defaultMaxBrowserOpensDay), menuInitialized: false, systrayInterface: &MockSystray{}, lastMenuTitles: nil, // This is nil on first run - the bug condition @@ -169,7 +169,7 @@ func TestHiddenOrgChangesMenu(t *testing.T) { hiddenOrgs: make(map[string]bool), seenOrgs: make(map[string]bool), blockedPRTimes: make(map[string]time.Time), - browserRateLimiter: NewBrowserRateLimiter(30*time.Second, 5, defaultMaxBrowserOpensDay), + browserRateLimiter: NewBrowserRateLimiter(startupGracePeriod, 5, defaultMaxBrowserOpensDay), systrayInterface: &MockSystray{}, incoming: []PR{ {Repository: "org1/repo1", Number: 1, Title: "PR 1", URL: "https://github.com/org1/repo1/pull/1"}, diff --git a/cmd/goose/notifications.go b/cmd/goose/notifications.go index e00126d..a1b3870 100644 --- a/cmd/goose/notifications.go +++ b/cmd/goose/notifications.go @@ -26,8 +26,17 @@ func (app *App) processNotifications(ctx context.Context) { copy(outgoing, app.outgoing) app.mu.RUnlock() + // Determine if this is the initial discovery + isInitialDiscovery := !app.hasPerformedInitialDiscovery + // Let the state manager figure out what needs notifications - toNotify := app.stateManager.UpdatePRs(incoming, outgoing, hiddenOrgs) + toNotify := app.stateManager.UpdatePRs(incoming, outgoing, hiddenOrgs, isInitialDiscovery) + + // Mark that we've performed initial discovery + if isInitialDiscovery { + app.hasPerformedInitialDiscovery = true + slog.Info("[STATE] Initial discovery completed", "incoming_count", len(incoming), "outgoing_count", len(outgoing)) + } // Update deprecated fields for test compatibility app.mu.Lock() @@ -81,8 +90,9 @@ func (app *App) processNotifications(ctx context.Context) { // Update menu if we sent notifications if len(toNotify) > 0 { - slog.Debug("[NOTIFY] Updating menu after notifications") + slog.Info("[FLOW] Updating menu after sending notifications", "notified_count", len(toNotify)) app.updateMenu(ctx) + slog.Info("[FLOW] Menu update after notifications completed") } } diff --git a/cmd/goose/pr_state.go b/cmd/goose/pr_state.go index 4250673..ac955b7 100644 --- a/cmd/goose/pr_state.go +++ b/cmd/goose/pr_state.go @@ -9,10 +9,11 @@ import ( // PRState tracks the complete state of a PR including blocking history. type PRState struct { - FirstBlockedAt time.Time - LastSeenBlocked time.Time - PR PR - HasNotified bool + FirstBlockedAt time.Time + LastSeenBlocked time.Time + PR PR + HasNotified bool + IsInitialDiscovery bool // True if this PR was discovered as already blocked during startup } // PRStateManager manages all PR states with proper synchronization. @@ -34,13 +35,18 @@ func NewPRStateManager(startTime time.Time) *PRStateManager { // UpdatePRs updates the state with new PR data and returns which PRs need notifications. // This function is thread-safe and handles all state transitions atomically. -func (m *PRStateManager) UpdatePRs(incoming, outgoing []PR, hiddenOrgs map[string]bool) (toNotify []PR) { +// isInitialDiscovery should be true only on the very first poll to prevent notifications for already-blocked PRs. +func (m *PRStateManager) UpdatePRs(incoming, outgoing []PR, hiddenOrgs map[string]bool, isInitialDiscovery bool) (toNotify []PR) { m.mu.Lock() defer m.mu.Unlock() now := time.Now() inGracePeriod := time.Since(m.startTime) < time.Duration(m.gracePeriodSeconds)*time.Second + slog.Debug("[STATE] UpdatePRs called", + "incoming", len(incoming), "outgoing", len(outgoing), + "existing_states", len(m.states), "in_grace_period", inGracePeriod, "is_initial_discovery", isInitialDiscovery) + // Track which PRs are currently blocked currentlyBlocked := make(map[string]bool) @@ -62,7 +68,10 @@ func (m *PRStateManager) UpdatePRs(incoming, outgoing []PR, hiddenOrgs map[strin if !isBlocked { // PR is not blocked - remove from tracking if it was if state, exists := m.states[pr.URL]; exists && state != nil { - slog.Info("[STATE] PR no longer blocked", "repo", pr.Repository, "number", pr.Number) + slog.Info("[STATE] State transition: blocked -> unblocked", + "repo", pr.Repository, "number", pr.Number, "url", pr.URL, + "was_blocked_since", state.FirstBlockedAt.Format(time.RFC3339), + "blocked_duration", time.Since(state.FirstBlockedAt).Round(time.Second)) delete(m.states, pr.URL) } continue @@ -73,32 +82,67 @@ func (m *PRStateManager) UpdatePRs(incoming, outgoing []PR, hiddenOrgs map[strin // Get or create state for this PR state, exists := m.states[pr.URL] if !exists { - // New blocked PR! - state = &PRState{ - PR: pr, - FirstBlockedAt: now, - LastSeenBlocked: now, - HasNotified: false, - } - m.states[pr.URL] = state - - slog.Info("[STATE] New blocked PR detected", "repo", pr.Repository, "number", pr.Number) - - // Should we notify? - if !inGracePeriod && !state.HasNotified { - slog.Debug("[STATE] Will notify for newly blocked PR", "repo", pr.Repository, "number", pr.Number) - toNotify = append(toNotify, pr) - state.HasNotified = true - } else if inGracePeriod { - slog.Debug("[STATE] In grace period, not notifying", "repo", pr.Repository, "number", pr.Number) + // This PR was not in our state before + if isInitialDiscovery { + // Initial discovery: PR was already blocked when we started, no state transition + state = &PRState{ + PR: pr, + FirstBlockedAt: now, + LastSeenBlocked: now, + HasNotified: false, // Don't consider this as notified since no actual notification was sent + IsInitialDiscovery: true, // Mark as initial discovery to prevent notifications and party poppers + } + m.states[pr.URL] = state + + slog.Info("[STATE] Initial discovery: already blocked PR", + "repo", pr.Repository, + "number", pr.Number, + "url", pr.URL, + "pr_updated_at", pr.UpdatedAt.Format(time.RFC3339), + "firstBlockedAt", state.FirstBlockedAt.Format(time.RFC3339)) + } else { + // Actual state transition: unblocked -> blocked + state = &PRState{ + PR: pr, + FirstBlockedAt: now, + LastSeenBlocked: now, + HasNotified: false, + IsInitialDiscovery: false, // This is a real state transition + } + m.states[pr.URL] = state + + slog.Info("[STATE] State transition: unblocked -> blocked", + "repo", pr.Repository, + "number", pr.Number, + "url", pr.URL, + "pr_updated_at", pr.UpdatedAt.Format(time.RFC3339), + "firstBlockedAt", state.FirstBlockedAt.Format(time.RFC3339), + "inGracePeriod", inGracePeriod) + + // Should we notify for actual state transitions? + if !inGracePeriod && !state.HasNotified { + slog.Debug("[STATE] Will notify for newly blocked PR", "repo", pr.Repository, "number", pr.Number) + toNotify = append(toNotify, pr) + state.HasNotified = true + } else if inGracePeriod { + slog.Debug("[STATE] In grace period, not notifying", "repo", pr.Repository, "number", pr.Number) + } } } else { - // PR was already blocked + // PR was already blocked in our state - just update data, preserve FirstBlockedAt + originalFirstBlocked := state.FirstBlockedAt state.LastSeenBlocked = now state.PR = pr // Update PR data + slog.Debug("[STATE] State transition: blocked -> blocked (no change)", + "repo", pr.Repository, "number", pr.Number, "url", pr.URL, + "original_first_blocked", originalFirstBlocked.Format(time.RFC3339), + "time_since_first_blocked", time.Since(originalFirstBlocked).Round(time.Second), + "has_notified", state.HasNotified) + // If we haven't notified yet and we're past grace period, notify now - if !state.HasNotified && !inGracePeriod { + // But don't notify for initial discovery PRs + if !state.HasNotified && !inGracePeriod && !state.IsInitialDiscovery { slog.Info("[STATE] Past grace period, notifying for previously blocked PR", "repo", pr.Repository, "number", pr.Number) toNotify = append(toNotify, pr) @@ -108,13 +152,26 @@ func (m *PRStateManager) UpdatePRs(incoming, outgoing []PR, hiddenOrgs map[strin } // Clean up states for PRs that are no longer in our lists - for url := range m.states { + // Add more conservative cleanup with logging + removedCount := 0 + for url, state := range m.states { if !currentlyBlocked[url] { - slog.Debug("[STATE] Removing stale state for PR", "url", url) + timeSinceLastSeen := time.Since(state.LastSeenBlocked) + slog.Info("[STATE] Removing stale PR state (no longer blocked)", + "url", url, "repo", state.PR.Repository, "number", state.PR.Number, + "first_blocked_at", state.FirstBlockedAt.Format(time.RFC3339), + "last_seen_blocked", state.LastSeenBlocked.Format(time.RFC3339), + "time_since_last_seen", timeSinceLastSeen.Round(time.Second), + "was_notified", state.HasNotified) delete(m.states, url) + removedCount++ } } + if removedCount > 0 { + slog.Info("[STATE] State cleanup completed", "removed_states", removedCount, "remaining_states", len(m.states)) + } + return toNotify } diff --git a/cmd/goose/pr_state_test.go b/cmd/goose/pr_state_test.go index 9beb87f..a5e99e3 100644 --- a/cmd/goose/pr_state_test.go +++ b/cmd/goose/pr_state_test.go @@ -15,22 +15,23 @@ func TestPRStateManager(t *testing.T) { Number: 1, URL: "https://github.com/test/repo/pull/1", NeedsReview: true, + UpdatedAt: time.Now(), // Recently updated PR } - toNotify := mgr.UpdatePRs([]PR{pr1}, []PR{}, map[string]bool{}) + toNotify := mgr.UpdatePRs([]PR{pr1}, []PR{}, map[string]bool{}, false) if len(toNotify) != 1 { t.Errorf("Expected 1 PR to notify, got %d", len(toNotify)) } // Test 2: Same PR on next update should not notify again - toNotify = mgr.UpdatePRs([]PR{pr1}, []PR{}, map[string]bool{}) + toNotify = mgr.UpdatePRs([]PR{pr1}, []PR{}, map[string]bool{}, false) if len(toNotify) != 0 { t.Errorf("Expected 0 PRs to notify (already notified), got %d", len(toNotify)) } // Test 3: PR becomes unblocked pr1.NeedsReview = false - toNotify = mgr.UpdatePRs([]PR{pr1}, []PR{}, map[string]bool{}) + toNotify = mgr.UpdatePRs([]PR{pr1}, []PR{}, map[string]bool{}, false) if len(toNotify) != 0 { t.Errorf("Expected 0 PRs to notify (unblocked), got %d", len(toNotify)) } @@ -42,7 +43,7 @@ func TestPRStateManager(t *testing.T) { // Test 4: PR becomes blocked again - should notify pr1.NeedsReview = true - toNotify = mgr.UpdatePRs([]PR{pr1}, []PR{}, map[string]bool{}) + toNotify = mgr.UpdatePRs([]PR{pr1}, []PR{}, map[string]bool{}, false) if len(toNotify) != 1 { t.Errorf("Expected 1 PR to notify (re-blocked), got %d", len(toNotify)) } @@ -58,9 +59,10 @@ func TestPRStateManagerGracePeriod(t *testing.T) { Number: 1, URL: "https://github.com/test/repo/pull/1", NeedsReview: true, + UpdatedAt: time.Now(), // Recently updated PR } - toNotify := mgr.UpdatePRs([]PR{pr1}, []PR{}, map[string]bool{}) + toNotify := mgr.UpdatePRs([]PR{pr1}, []PR{}, map[string]bool{}, false) if len(toNotify) != 0 { t.Errorf("Expected 0 PRs to notify during grace period, got %d", len(toNotify)) } @@ -74,7 +76,7 @@ func TestPRStateManagerGracePeriod(t *testing.T) { mgr.startTime = time.Now().Add(-60 * time.Second) // Same PR should now notify since we're past grace period and haven't notified yet - toNotify = mgr.UpdatePRs([]PR{pr1}, []PR{}, map[string]bool{}) + toNotify = mgr.UpdatePRs([]PR{pr1}, []PR{}, map[string]bool{}, false) if len(toNotify) != 1 { t.Errorf("Expected 1 PR to notify after grace period, got %d", len(toNotify)) } @@ -88,6 +90,7 @@ func TestPRStateManagerHiddenOrgs(t *testing.T) { Number: 1, URL: "https://github.com/hidden-org/repo/pull/1", IsBlocked: true, + UpdatedAt: time.Now(), // Recently updated PR } pr2 := PR{ @@ -95,13 +98,14 @@ func TestPRStateManagerHiddenOrgs(t *testing.T) { Number: 2, URL: "https://github.com/visible-org/repo/pull/2", IsBlocked: true, + UpdatedAt: time.Now(), // Recently updated PR } hiddenOrgs := map[string]bool{ "hidden-org": true, } - toNotify := mgr.UpdatePRs([]PR{}, []PR{pr1, pr2}, hiddenOrgs) + toNotify := mgr.UpdatePRs([]PR{}, []PR{pr1, pr2}, hiddenOrgs, false) // Should only notify for visible org if len(toNotify) != 1 { @@ -111,3 +115,185 @@ func TestPRStateManagerHiddenOrgs(t *testing.T) { t.Errorf("Expected visible PR to be notified, got %s", toNotify[0].URL) } } + +// TestInitialDiscoveryNoNotifications tests that PRs discovered as already blocked on startup don't notify +func TestInitialDiscoveryNoNotifications(t *testing.T) { + mgr := NewPRStateManager(time.Now().Add(-60 * time.Second)) // Past grace period + + // Create some PRs that are already blocked + pr1 := PR{ + Repository: "test/repo1", + Number: 1, + URL: "https://github.com/test/repo1/pull/1", + NeedsReview: true, + UpdatedAt: time.Now(), + } + + pr2 := PR{ + Repository: "test/repo2", + Number: 2, + URL: "https://github.com/test/repo2/pull/2", + IsBlocked: true, + UpdatedAt: time.Now(), + } + + // Initial discovery should NOT notify even though we're past grace period + toNotify := mgr.UpdatePRs([]PR{pr1}, []PR{pr2}, map[string]bool{}, true) + if len(toNotify) != 0 { + t.Errorf("Expected 0 PRs to notify on initial discovery, got %d", len(toNotify)) + } + + // Verify states were created and marked as initial discovery + state1, exists1 := mgr.PRState(pr1.URL) + if !exists1 { + t.Error("Expected state to exist for pr1") + } + if !state1.IsInitialDiscovery { + t.Error("Expected pr1 state to be marked as initial discovery") + } + + state2, exists2 := mgr.PRState(pr2.URL) + if !exists2 { + t.Error("Expected state to exist for pr2") + } + if !state2.IsInitialDiscovery { + t.Error("Expected pr2 state to be marked as initial discovery") + } + + // Now a subsequent update with the same PRs should still not notify + toNotify = mgr.UpdatePRs([]PR{pr1}, []PR{pr2}, map[string]bool{}, false) + if len(toNotify) != 0 { + t.Errorf("Expected 0 PRs to notify on subsequent update (no state change), got %d", len(toNotify)) + } + + // But if a NEW blocked PR appears later, it should notify + pr3 := PR{ + Repository: "test/repo3", + Number: 3, + URL: "https://github.com/test/repo3/pull/3", + NeedsReview: true, + UpdatedAt: time.Now(), + } + + toNotify = mgr.UpdatePRs([]PR{pr1, pr3}, []PR{pr2}, map[string]bool{}, false) + if len(toNotify) != 1 { + t.Errorf("Expected 1 PR to notify for newly blocked PR, got %d", len(toNotify)) + } + if len(toNotify) > 0 && toNotify[0].URL != pr3.URL { + t.Errorf("Expected pr3 to be notified, got %s", toNotify[0].URL) + } + + // Verify that initial discovery states are marked correctly + state3, exists3 := mgr.PRState(pr3.URL) + if !exists3 { + t.Error("Expected state to exist for pr3") + } + if state3.IsInitialDiscovery { + t.Error("Expected pr3 to NOT be marked as initial discovery (it was a real transition)") + } +} + +// TestPRStateManagerPreservesFirstBlockedTime tests that FirstBlockedAt is not reset +// when the same blocked PR is processed on subsequent polls +func TestPRStateManagerPreservesFirstBlockedTime(t *testing.T) { + mgr := NewPRStateManager(time.Now().Add(-60 * time.Second)) + + // Create a blocked PR + pr := PR{ + Repository: "test/repo", + Number: 1, + URL: "https://github.com/test/repo/pull/1", + NeedsReview: true, + UpdatedAt: time.Now(), + } + + // First call - should create state and notify (state transition: none -> blocked) + toNotify := mgr.UpdatePRs([]PR{pr}, []PR{}, map[string]bool{}, false) + if len(toNotify) != 1 { + t.Fatalf("Expected 1 PR to notify on first call, got %d", len(toNotify)) + } + + // Get the initial state + state1, exists := mgr.PRState(pr.URL) + if !exists { + t.Fatal("Expected state to exist after first call") + } + originalFirstBlocked := state1.FirstBlockedAt + + // Wait a small amount to ensure timestamps would be different + time.Sleep(10 * time.Millisecond) + + // Second call with same PR - should NOT notify and should preserve FirstBlockedAt + // (no state transition: blocked -> blocked) + toNotify = mgr.UpdatePRs([]PR{pr}, []PR{}, map[string]bool{}, false) + if len(toNotify) != 0 { + t.Errorf("Expected 0 PRs to notify on second call (no state transition), got %d", len(toNotify)) + } + + // Get the state again + state2, exists := mgr.PRState(pr.URL) + if !exists { + t.Fatal("Expected state to exist after second call") + } + + // FirstBlockedAt should be exactly the same + if !state2.FirstBlockedAt.Equal(originalFirstBlocked) { + t.Errorf("FirstBlockedAt was changed! Original: %s, New: %s", + originalFirstBlocked.Format(time.RFC3339Nano), + state2.FirstBlockedAt.Format(time.RFC3339Nano)) + } + + // HasNotified should still be true + if !state2.HasNotified { + t.Error("HasNotified should remain true") + } + + t.Logf("SUCCESS: FirstBlockedAt preserved across polls: %s", originalFirstBlocked.Format(time.RFC3339)) +} + +// TestPRStateTransitions tests the core state transition logic +func TestPRStateTransitions(t *testing.T) { + mgr := NewPRStateManager(time.Now().Add(-60 * time.Second)) + + pr := PR{ + Repository: "test/repo", + Number: 1, + URL: "https://github.com/test/repo/pull/1", + NeedsReview: true, + UpdatedAt: time.Now(), + } + + // Transition 1: none -> blocked (should notify) + toNotify := mgr.UpdatePRs([]PR{pr}, []PR{}, map[string]bool{}, false) + if len(toNotify) != 1 { + t.Errorf("Expected notification for none->blocked transition, got %d", len(toNotify)) + } + + // Transition 2: blocked -> unblocked (should clean up state) + pr.NeedsReview = false + toNotify = mgr.UpdatePRs([]PR{pr}, []PR{}, map[string]bool{}, false) + if len(toNotify) != 0 { + t.Errorf("Expected no notification for blocked->unblocked transition, got %d", len(toNotify)) + } + + // Verify state was removed + if _, exists := mgr.PRState(pr.URL); exists { + t.Error("Expected state to be removed when PR becomes unblocked") + } + + // Transition 3: unblocked -> blocked again (should notify again as new state) + pr.NeedsReview = true + toNotify = mgr.UpdatePRs([]PR{pr}, []PR{}, map[string]bool{}, false) + if len(toNotify) != 1 { + t.Errorf("Expected notification for unblocked->blocked transition, got %d", len(toNotify)) + } + + // Verify new state was created + state, exists := mgr.PRState(pr.URL) + if !exists { + t.Error("Expected new state to be created for unblocked->blocked transition") + } + if state.HasNotified != true { + t.Error("Expected new state to be marked as notified") + } +} diff --git a/cmd/goose/reliability.go b/cmd/goose/reliability.go new file mode 100644 index 0000000..5882181 --- /dev/null +++ b/cmd/goose/reliability.go @@ -0,0 +1,183 @@ +// Package main - reliability.go provides reliability improvements and error recovery. +package main + +import ( + "fmt" + "log/slog" + "runtime/debug" + "sync" + "time" +) + +// safeExecute runs a function with panic recovery and logging. +func safeExecute(operation string, fn func() error) (err error) { + defer func() { + if r := recover(); r != nil { + stack := debug.Stack() + err = fmt.Errorf("panic in %s: %v\nStack: %s", operation, r, stack) + slog.Error("[RELIABILITY] Panic recovered", + "operation", operation, + "panic", r, + "stack", string(stack)) + } + }() + + start := time.Now() + err = fn() + duration := time.Since(start) + + if err != nil { + slog.Error("[RELIABILITY] Operation failed", + "operation", operation, + "error", err, + "duration", duration) + } else if duration > 5*time.Second { + slog.Warn("[RELIABILITY] Slow operation", + "operation", operation, + "duration", duration) + } + + return err +} + +// circuitBreaker provides circuit breaker pattern for external API calls. +type circuitBreaker struct { + mu sync.RWMutex + lastFailureTime time.Time + timeout time.Duration + name string + state string // "closed", "open", "half-open" + failures int + threshold int +} + +func newCircuitBreaker(name string, threshold int, timeout time.Duration) *circuitBreaker { + return &circuitBreaker{ + name: name, + threshold: threshold, + timeout: timeout, + state: "closed", + } +} + +func (cb *circuitBreaker) call(fn func() error) error { + cb.mu.Lock() + defer cb.mu.Unlock() + + // Check if circuit is open + if cb.state == "open" { + if time.Since(cb.lastFailureTime) > cb.timeout { + cb.state = "half-open" + slog.Info("[CIRCUIT] Circuit breaker transitioning to half-open", + "name", cb.name) + } else { + return fmt.Errorf("circuit breaker open for %s", cb.name) + } + } + + // Execute the function + err := fn() + if err != nil { + cb.failures++ + cb.lastFailureTime = time.Now() + + if cb.failures >= cb.threshold { + cb.state = "open" + slog.Error("[CIRCUIT] Circuit breaker opened", + "name", cb.name, + "failures", cb.failures, + "threshold", cb.threshold) + } + + return err + } + + // Success - reset on half-open or reduce failure count + if cb.state == "half-open" { + cb.state = "closed" + cb.failures = 0 + slog.Info("[CIRCUIT] Circuit breaker closed after successful call", + "name", cb.name) + } else if cb.failures > 0 { + cb.failures-- + } + + return nil +} + +// healthMonitor tracks application health metrics. +type healthMonitor struct { + mu sync.RWMutex + lastCheckTime time.Time + uptime time.Time + apiCalls int64 + apiErrors int64 + cacheHits int64 + cacheMisses int64 +} + +func newHealthMonitor() *healthMonitor { + return &healthMonitor{ + uptime: time.Now(), + lastCheckTime: time.Now(), + } +} + +func (hm *healthMonitor) recordAPICall(success bool) { + hm.mu.Lock() + defer hm.mu.Unlock() + + hm.apiCalls++ + if !success { + hm.apiErrors++ + } + hm.lastCheckTime = time.Now() +} + +func (hm *healthMonitor) recordCacheAccess(hit bool) { + hm.mu.Lock() + defer hm.mu.Unlock() + + if hit { + hm.cacheHits++ + } else { + hm.cacheMisses++ + } +} + +func (hm *healthMonitor) getMetrics() map[string]interface{} { + hm.mu.RLock() + defer hm.mu.RUnlock() + + errorRate := float64(0) + if hm.apiCalls > 0 { + errorRate = float64(hm.apiErrors) / float64(hm.apiCalls) * 100 + } + + cacheHitRate := float64(0) + totalCacheAccess := hm.cacheHits + hm.cacheMisses + if totalCacheAccess > 0 { + cacheHitRate = float64(hm.cacheHits) / float64(totalCacheAccess) * 100 + } + + return map[string]interface{}{ + "uptime": time.Since(hm.uptime), + "api_calls": hm.apiCalls, + "api_errors": hm.apiErrors, + "error_rate": errorRate, + "cache_hits": hm.cacheHits, + "cache_misses": hm.cacheMisses, + "cache_hit_rate": cacheHitRate, + "last_check": hm.lastCheckTime, + } +} + +func (hm *healthMonitor) logMetrics() { + metrics := hm.getMetrics() + slog.Info("[HEALTH] Application metrics", + "uptime", metrics["uptime"], + "api_calls", metrics["api_calls"], + "api_errors", metrics["api_errors"], + "error_rate_pct", fmt.Sprintf("%.1f", metrics["error_rate"]), + "cache_hit_rate_pct", fmt.Sprintf("%.1f", metrics["cache_hit_rate"])) +} diff --git a/cmd/goose/ui.go b/cmd/goose/ui.go index 2d82f46..4a1e5f3 100644 --- a/cmd/goose/ui.go +++ b/cmd/goose/ui.go @@ -110,10 +110,13 @@ func (app *App) countPRs() PRCounts { now := time.Now() staleThreshold := now.Add(-stalePRThreshold) + slog.Info("[MENU] Counting incoming PRs", "total_incoming", len(app.incoming)) + filteredIncoming := 0 for i := range app.incoming { // Check if org is hidden org := extractOrgFromRepo(app.incoming[i].Repository) if org != "" && app.hiddenOrgs[org] { + filteredIncoming++ continue } @@ -122,23 +125,65 @@ func (app *App) countPRs() PRCounts { if app.incoming[i].NeedsReview { incomingBlocked++ } + } else { + filteredIncoming++ } } - + slog.Info("[MENU] Incoming PR count results", + "total_before_filter", len(app.incoming), + "total_after_filter", incomingCount, + "filtered_out", filteredIncoming, + "blocked_count", incomingBlocked) + + slog.Info("[MENU] Counting outgoing PRs", + "total_outgoing", len(app.outgoing), + "hideStaleIncoming", app.hideStaleIncoming, + "staleThreshold", staleThreshold.Format(time.RFC3339)) for i := range app.outgoing { + pr := app.outgoing[i] // Check if org is hidden - org := extractOrgFromRepo(app.outgoing[i].Repository) - if org != "" && app.hiddenOrgs[org] { + org := extractOrgFromRepo(pr.Repository) + hiddenByOrg := org != "" && app.hiddenOrgs[org] + isStale := pr.UpdatedAt.Before(staleThreshold) + + // Log every PR with its filtering status + slog.Info("[MENU] Processing outgoing PR", + "repo", pr.Repository, + "number", pr.Number, + "org", org, + "hidden_org", hiddenByOrg, + "updated_at", pr.UpdatedAt.Format(time.RFC3339), + "is_stale", isStale, + "hideStale_enabled", app.hideStaleIncoming, + "blocked", pr.IsBlocked, + "url", pr.URL) + + if hiddenByOrg { + slog.Info("[MENU] ❌ Filtering out outgoing PR (hidden org)", + "repo", pr.Repository, "number", pr.Number, + "org", org, "url", pr.URL) continue } - if !app.hideStaleIncoming || app.outgoing[i].UpdatedAt.After(staleThreshold) { + if !app.hideStaleIncoming || !isStale { outgoingCount++ - if app.outgoing[i].IsBlocked { + if pr.IsBlocked { outgoingBlocked++ } + slog.Info("[MENU] ✅ Including outgoing PR in count", + "repo", pr.Repository, "number", pr.Number, + "blocked", pr.IsBlocked, "url", pr.URL) + } else { + slog.Info("[MENU] ❌ Filtering out outgoing PR (stale)", + "repo", pr.Repository, "number", pr.Number, + "updated_at", pr.UpdatedAt.Format(time.RFC3339), + "url", pr.URL) } } + slog.Info("[MENU] Outgoing PR count results", + "total_before_filter", len(app.outgoing), + "total_after_filter", outgoingCount, + "blocked_count", outgoingBlocked) return PRCounts{ IncomingTotal: incomingCount, IncomingBlocked: incomingBlocked, @@ -176,7 +221,12 @@ func (app *App) setTrayTitle() { // addPRSection adds a section of PRs to the menu. func (app *App) addPRSection(ctx context.Context, prs []PR, sectionTitle string, blockedCount int) { + slog.Debug("[MENU] addPRSection called", + "section", sectionTitle, + "pr_count", len(prs), + "blocked_count", blockedCount) if len(prs) == 0 { + slog.Debug("[MENU] No PRs to add in section", "section", sectionTitle) return } @@ -211,35 +261,55 @@ func (app *App) addPRSection(ctx context.Context, prs []PR, sectionTitle string, app.mu.RUnlock() // Add PR items in sorted order + itemsAdded := 0 for prIndex := range sortedPRs { // Apply filters // Skip PRs from hidden orgs org := extractOrgFromRepo(sortedPRs[prIndex].Repository) if org != "" && hiddenOrgs[org] { + slog.Debug("[MENU] Skipping PR in addPRSection (hidden org)", + "section", sectionTitle, + "repo", sortedPRs[prIndex].Repository, + "number", sortedPRs[prIndex].Number, + "org", org) continue } // Skip stale PRs if configured if hideStale && sortedPRs[prIndex].UpdatedAt.Before(time.Now().Add(-stalePRThreshold)) { + slog.Debug("[MENU] Skipping PR in addPRSection (stale)", + "section", sectionTitle, + "repo", sortedPRs[prIndex].Repository, + "number", sortedPRs[prIndex].Number, + "updated_at", sortedPRs[prIndex].UpdatedAt) continue } title := fmt.Sprintf("%s #%d", sortedPRs[prIndex].Repository, sortedPRs[prIndex].Number) - // Add bullet point or emoji for blocked PRs + + // Add action code if present + if sortedPRs[prIndex].ActionKind != "" { + title = fmt.Sprintf("%s — %s", title, sortedPRs[prIndex].ActionKind) + } + + // Add bullet point or emoji based on PR status if sortedPRs[prIndex].NeedsReview || sortedPRs[prIndex].IsBlocked { // Get the blocked time from state manager prState, hasState := app.stateManager.PRState(sortedPRs[prIndex].URL) - // Show emoji for PRs blocked within the last 5 minutes - if hasState && !prState.FirstBlockedAt.IsZero() && time.Since(prState.FirstBlockedAt) < blockedPRIconDuration { + // Show emoji for PRs blocked within the last 5 minutes (but only for real state transitions, not initial discoveries) + if hasState && !prState.FirstBlockedAt.IsZero() && time.Since(prState.FirstBlockedAt) < blockedPRIconDuration && !prState.IsInitialDiscovery { timeSinceBlocked := time.Since(prState.FirstBlockedAt) // Use party popper for outgoing PRs, goose for incoming PRs if sectionTitle == "Outgoing" { title = fmt.Sprintf("🎉 %s", title) - slog.Debug("[MENU] Adding party popper to outgoing PR", + slog.Info("[MENU] Adding party popper to outgoing PR", + "repo", sortedPRs[prIndex].Repository, + "number", sortedPRs[prIndex].Number, "url", sortedPRs[prIndex].URL, - "blocked_ago", timeSinceBlocked, - "remaining", blockedPRIconDuration-timeSinceBlocked) + "firstBlockedAt", prState.FirstBlockedAt.Format(time.RFC3339), + "blocked_ago", timeSinceBlocked.Round(time.Second), + "remaining", (blockedPRIconDuration - timeSinceBlocked).Round(time.Second)) } else { title = fmt.Sprintf("🪿 %s", title) slog.Debug("[MENU] Adding goose to incoming PR", @@ -248,8 +318,9 @@ func (app *App) addPRSection(ctx context.Context, prs []PR, sectionTitle string, "remaining", blockedPRIconDuration-timeSinceBlocked) } } else { - title = fmt.Sprintf("• %s", title) - // Log when we transition from emoji to bullet point + // Use block/square icon for blocked PRs + title = fmt.Sprintf("■ %s", title) + // Log when we transition from emoji to block icon if hasState && !prState.FirstBlockedAt.IsZero() { timeSinceBlocked := time.Since(prState.FirstBlockedAt) if sectionTitle == "Outgoing" { @@ -265,6 +336,9 @@ func (app *App) addPRSection(ctx context.Context, prs []PR, sectionTitle string, } } } + } else if sortedPRs[prIndex].ActionKind != "" { + // PR has an action but isn't blocked - add bullet to indicate it could use input + title = fmt.Sprintf("• %s", title) } // Format age inline for tooltip duration := time.Since(sortedPRs[prIndex].UpdatedAt) @@ -288,6 +362,14 @@ func (app *App) addPRSection(ctx context.Context, prs []PR, sectionTitle string, } // Create PR menu item + itemsAdded++ + slog.Debug("[MENU] Adding PR to menu", + "section", sectionTitle, + "title", title, + "repo", sortedPRs[prIndex].Repository, + "number", sortedPRs[prIndex].Number, + "url", sortedPRs[prIndex].URL, + "blocked", sortedPRs[prIndex].NeedsReview || sortedPRs[prIndex].IsBlocked) item := app.systrayInterface.AddMenuItem(title, tooltip) // Capture URL and action to avoid loop variable capture bug @@ -299,6 +381,10 @@ func (app *App) addPRSection(ctx context.Context, prs []PR, sectionTitle string, } }) } + slog.Info("[MENU] Added PR section", + "section", sectionTitle, + "items_added", itemsAdded, + "filtered_out", len(sortedPRs)-itemsAdded) } // generateMenuTitles generates the list of menu item titles that would be shown @@ -387,19 +473,55 @@ func (app *App) generatePRSectionTitles(prs []PR, sectionTitle string, hiddenOrg title := fmt.Sprintf("%s #%d", sortedPRs[prIndex].Repository, sortedPRs[prIndex].Number) + // Add action code if present + if sortedPRs[prIndex].ActionKind != "" { + title = fmt.Sprintf("%s — %s", title, sortedPRs[prIndex].ActionKind) + } + // Add bullet point or emoji for blocked PRs (same logic as in addPRSection) if sortedPRs[prIndex].NeedsReview || sortedPRs[prIndex].IsBlocked { prState, hasState := app.stateManager.PRState(sortedPRs[prIndex].URL) - if hasState && !prState.FirstBlockedAt.IsZero() && time.Since(prState.FirstBlockedAt) < blockedPRIconDuration { + if hasState && !prState.FirstBlockedAt.IsZero() && time.Since(prState.FirstBlockedAt) < blockedPRIconDuration && !prState.IsInitialDiscovery { + timeSinceBlocked := time.Since(prState.FirstBlockedAt) if sectionTitle == "Outgoing" { title = fmt.Sprintf("🎉 %s", title) + slog.Info("[MENU] Adding party popper to outgoing PR in generateMenuTitles", + "repo", sortedPRs[prIndex].Repository, + "number", sortedPRs[prIndex].Number, + "url", sortedPRs[prIndex].URL, + "firstBlockedAt", prState.FirstBlockedAt.Format(time.RFC3339), + "blocked_ago", timeSinceBlocked.Round(time.Second), + "remaining", (blockedPRIconDuration - timeSinceBlocked).Round(time.Second)) } else { title = fmt.Sprintf("🪿 %s", title) + slog.Debug("[MENU] Adding goose to incoming PR in generateMenuTitles", + "url", sortedPRs[prIndex].URL, + "blocked_ago", timeSinceBlocked, + "remaining", blockedPRIconDuration-timeSinceBlocked) } } else { - title = fmt.Sprintf("• %s", title) + // Use block/square icon for blocked PRs + title = fmt.Sprintf("■ %s", title) + // Log when we use block icon instead of emoji + if hasState && !prState.FirstBlockedAt.IsZero() { + timeSinceBlocked := time.Since(prState.FirstBlockedAt) + if sectionTitle == "Outgoing" { + slog.Debug("[MENU] Using block icon instead of party popper in generateMenuTitles", + "url", sortedPRs[prIndex].URL, + "blocked_ago", timeSinceBlocked.Round(time.Second), + "icon_duration", blockedPRIconDuration) + } + } else if !hasState { + slog.Debug("[MENU] No state found for blocked PR, using block icon", + "url", sortedPRs[prIndex].URL, + "repo", sortedPRs[prIndex].Repository, + "number", sortedPRs[prIndex].Number) + } } + } else if sortedPRs[prIndex].ActionKind != "" { + // PR has an action but isn't blocked - add bullet to indicate it could use input + title = fmt.Sprintf("• %s", title) } titles = append(titles, title) @@ -570,11 +692,17 @@ func (app *App) rebuildMenu(ctx context.Context) { app.systrayInterface.AddSeparator() // Outgoing section + slog.Info("[MENU] Building outgoing section", + "total_count", counts.OutgoingTotal, + "blocked_count", counts.OutgoingBlocked) if counts.OutgoingTotal > 0 { app.mu.RLock() outgoing := app.outgoing app.mu.RUnlock() + slog.Debug("[MENU] Outgoing PRs to add", "count", len(outgoing)) app.addPRSection(ctx, outgoing, "Outgoing", counts.OutgoingBlocked) + } else { + slog.Info("[MENU] No outgoing PRs to display after filtering") } }