Reproduce late doctor storage errors and migration deletion timeouts

Author: robzolkos

internal/commands/doctor.go

@@ -22,6 +22,7 @@ import (
 	"github.com/basecamp/basecamp-sdk/go/pkg/basecamp"
 
 	"github.com/basecamp/basecamp-cli/internal/appctx"
+	"github.com/basecamp/basecamp-cli/internal/auth"
 	"github.com/basecamp/basecamp-cli/internal/config"
 	"github.com/basecamp/basecamp-cli/internal/harness"
 	"github.com/basecamp/basecamp-cli/internal/output"
@@ -787,6 +788,12 @@ func checkStoredCredentials(ctx context.Context, app *appctx.App, verbose bool)
 
 // checkAuthentication checks token validity.
 func checkAuthentication(ctx context.Context, app *appctx.App, verbose bool) Check {
+	return checkAuthenticationWith(ctx, app, verbose, app.Auth.GetStore().LoadContext, app.Auth.Refresh)
+}
+
+func checkAuthenticationWith(ctx context.Context, app *appctx.App, verbose bool,
+	load func(context.Context, string) (*auth.Credentials, error), refresh func(context.Context) error,
+) Check {
 	check := Check{
 		Name: "Authentication",
 	}
@@ -800,8 +807,7 @@ func checkAuthentication(ctx context.Context, app *appctx.App, verbose bool) Che
 
 	// Load credentials to check expiration
 	credKey := app.Auth.CredentialKey()
-	store := app.Auth.GetStore()
-	creds, err := store.Load(credKey)
+	creds, err := load(ctx, credKey)
 	if err != nil {
 		check.Status = "fail"
 		check.Message = "Cannot load credentials"
@@ -815,7 +821,7 @@ func checkAuthentication(ctx context.Context, app *appctx.App, verbose bool) Che
 
 		if expiresIn < 0 {
 			// Token expired - try to refresh
-			if err := app.Auth.Refresh(ctx); err != nil {
+			if err := refresh(ctx); err != nil {
 				check.Status = "fail"
 				check.Message = "Token expired and refresh failed"
 				// The failure's own remedy, not a blanket login: for an

internal/commands/doctor_test.go

@@ -6,6 +6,7 @@ import (
 	"debug/pe"
 	"encoding/binary"
 	"errors"
+	"fmt"
 	"net/http"
 	"os"
 	"path/filepath"
@@ -400,6 +401,71 @@ func TestDoctorDoesNotCallAnUnreadableStoreAMissingLogin(t *testing.T) {
 	}
 }
 
+func TestDoctorAuthenticationPreservesLaterStoreTimeouts(t *testing.T) {
+	for _, failure := range []string{"authentication read", "refresh read", "refresh write"} {
+		t.Run(failure, func(t *testing.T) {
+			app, _ := setupDoctorTestApp(t, "12345")
+			t.Setenv("BASECAMP_TOKEN", "")
+			creds := &auth.Credentials{
+				AccessToken: "test-token", RefreshToken: "test-refresh",
+				OAuthType: "bc5", ExpiresAt: time.Now().Add(time.Hour).Unix(),
+			}
+			if failure != "authentication read" {
+				creds.ExpiresAt = time.Now().Add(-time.Hour).Unix()
+			}
+			require.NoError(t, app.Auth.GetStore().Save(app.Auth.CredentialKey(), creds))
+			initial, unreadable := checkStoredCredentials(context.Background(), app, false)
+			require.False(t, unreadable)
+			require.Equal(t, "pass", initial.Status)
+
+			operation := "read"
+			if failure == "refresh write" {
+				operation = "write"
+			}
+			timeout := fmt.Errorf("keyring %s timed out: %w; set BASECAMP_NO_KEYRING=1", operation, context.DeadlineExceeded)
+			loads, refreshes := 0, 0
+			load := func(context.Context, string) (*auth.Credentials, error) {
+				loads++
+				if failure == "authentication read" || (failure == "refresh read" && loads == 2) {
+					return nil, timeout
+				}
+				return creds, nil
+			}
+			refresh := func(ctx context.Context) error {
+				refreshes++
+				if _, err := load(ctx, app.Auth.CredentialKey()); err != nil {
+					return err
+				}
+				return timeout // The refresh read succeeded, but saving its result timed out.
+			}
+			check := checkAuthenticationWith(context.Background(), app, false, load, refresh)
+			assert.Equal(t, "fail", check.Status)
+			assert.Contains(t, check.Message, "keyring "+operation+" timed out")
+			assert.Contains(t, check.Message, "BASECAMP_NO_KEYRING=1")
+			assert.NotContains(t, check.Hint, app.Auth.LoginCommand())
+			assert.Empty(t, buildDoctorBreadcrumbs([]Check{initial, check}, app.Auth.LoginCommand()))
+			if failure == "authentication read" {
+				assert.Equal(t, 1, loads)
+				assert.Zero(t, refreshes)
+			} else {
+				assert.Equal(t, 2, loads)
+				assert.Equal(t, 1, refreshes)
+			}
+		})
+	}
+}
+
+func TestDoctorAuthenticationBreadcrumbRequiresLoginRemedy(t *testing.T) {
+	for _, status := range []string{"fail", "warn"} {
+		check := Check{Name: "Authentication", Status: status, Hint: "Try again later"}
+		assert.Empty(t, buildDoctorBreadcrumbs([]Check{check}, "basecamp auth login"))
+	}
+	check := Check{Name: "Authentication", Status: "fail", Hint: "Run: basecamp auth login"}
+	crumbs := buildDoctorBreadcrumbs([]Check{check}, "basecamp auth login")
+	require.Len(t, crumbs, 1)
+	assert.Equal(t, "basecamp auth login", crumbs[0].Cmd)
+}
+
 func TestDoctorLegacyKeyringProbeIsBounded(t *testing.T) {
 	original := legacyKeyringGet
 	t.Cleanup(func() { legacyKeyringGet = original })

internal/commands/migrate_test.go

@@ -432,6 +432,59 @@ func TestMigrateKeyring_StalledKeyringIsBounded(t *testing.T) {
 	assert.EqualValues(t, 1, calls.Load())
 }
 
+func TestMigrateDeletionTimeoutDoesNotMarkCompletion(t *testing.T) {
+	for _, alreadyCopied := range []bool{false, true} {
+		t.Run(fmt.Sprintf("destination_exists=%t", alreadyCopied), func(t *testing.T) {
+			t.Setenv("HOME", t.TempDir())
+			t.Setenv("BASECAMP_NO_KEYRING", "")
+			t.Setenv("XDG_CONFIG_HOME", t.TempDir())
+			cacheBase := t.TempDir()
+			t.Setenv("XDG_CACHE_HOME", cacheBase)
+			require.NoError(t, os.MkdirAll(filepath.Join(cacheBase, "bcq"), 0700))
+
+			fk := newFakeKeyring()
+			fk.store[fk.key("bcq", "bcq::https://3.basecampapi.com")] = "legacy-value"
+			if alreadyCopied {
+				fk.store[fk.key("basecamp", "basecamp::https://3.basecampapi.com")] = "current-value"
+			}
+			fk.install(t)
+			originalTimeout := legacyKeyringTimeout
+			legacyKeyringTimeout = 40 * time.Millisecond
+			t.Cleanup(func() { legacyKeyringTimeout = originalTimeout })
+			release, finished := make(chan struct{}), make(chan struct{})
+			keyringOps.delete = func(string, string) error {
+				defer close(finished)
+				<-release
+				return nil
+			}
+			t.Cleanup(func() { close(release); <-finished })
+
+			cmd := NewMigrateCmd()
+			var out bytes.Buffer
+			cmd.SetOut(&out)
+			cmd.SetArgs(nil)
+			require.NoError(t, cmd.Execute())
+			var result MigrateResult
+			require.NoError(t, json.Unmarshal(out.Bytes(), &result))
+			assert.True(t, result.CacheMoved, "even a successful cache move must not hide incomplete keyring cleanup")
+			assert.Zero(t, result.KeyringMigrated)
+			require.Len(t, result.KeyringErrors, 1)
+			assert.Contains(t, result.KeyringErrors[0], "delete")
+			assert.Contains(t, result.KeyringErrors[0], "timed out")
+			assert.Contains(t, result.KeyringErrors[0], "BASECAMP_NO_KEYRING=1")
+			_, err := os.Stat(filepath.Join(config.GlobalConfigDir(), migratedMarker))
+			assert.True(t, os.IsNotExist(err), "migration must stay discoverable after a deletion timeout")
+			value, err := fk.get("basecamp", "basecamp::https://3.basecampapi.com")
+			require.NoError(t, err)
+			if alreadyCopied {
+				assert.Equal(t, "current-value", value)
+			} else {
+				assert.Equal(t, "legacy-value", value)
+			}
+		})
+	}
+}
+
 func TestMigrateSkipsKeyringWhenNoKeyring(t *testing.T) {
 	t.Setenv("BASECAMP_NO_KEYRING", "1")
 	t.Setenv("XDG_CONFIG_HOME", t.TempDir())