ipn/ipnlocal: add more logging during profile migration

Updates tailscale/corp#11883

Change-Id: I3a3ca8f25bfefca139115b25ec4161c069da7e4a
Signed-off-by: Andrew Dunham <andrew@du.nham.ca>

ipn/ipnlocal/profiles.go

@@ -24,6 +24,8 @@ import (
 
 var errAlreadyMigrated = errors.New("profile migration already completed")
 
+var debug = envknob.RegisterBool("TS_DEBUG_PROFILES")
+
 // profileManager is a wrapper around a StateStore that manages
 // multiple profiles and the current profile.
 type profileManager struct {
@@ -42,6 +44,13 @@ type profileManager struct {
 	isNewProfile bool
 }
 
+func (pm *profileManager) dlogf(format string, args ...any) {
+	if !debug() {
+		return
+	}
+	pm.logf(format, args...)
+}
+
 // CurrentUserID returns the current user ID. It is only non-empty on
 // Windows where we have a multi-user system.
 func (pm *profileManager) CurrentUserID() ipn.WindowsUserID {
@@ -66,8 +75,10 @@ func (pm *profileManager) SetCurrentUserID(uid ipn.WindowsUserID) error {
 	// Read the CurrentProfileKey from the store which stores
 	// the selected profile for the current user.
 	b, err := pm.store.ReadState(ipn.CurrentProfileKey(string(uid)))
+	pm.dlogf("SetCurrentUserID: ReadState(%q) = %v, %v", string(uid), len(b), err)
 	if err == ipn.ErrStateNotExist || len(b) == 0 {
 		if runtime.GOOS == "windows" {
+			pm.dlogf("SetCurrentUserID: windows: migrating from legacy preferences")
 			if err := pm.migrateFromLegacyPrefs(); err != nil && !errors.Is(err, errAlreadyMigrated) {
 				return err
 			}
@@ -81,6 +92,7 @@ func (pm *profileManager) SetCurrentUserID(uid ipn.WindowsUserID) error {
 	pk := ipn.StateKey(string(b))
 	prof := pm.findProfileByKey(pk)
 	if prof == nil {
+		pm.dlogf("SetCurrentUserID: no profile found for key: %q", pk)
 		pm.NewProfile()
 		return nil
 	}
@@ -555,6 +567,7 @@ func newProfileManagerWithGOOS(store ipn.StateStore, logf logger.Logf, goos stri
 		// and runtime must be valid Windows security identifier structures.
 	} else if len(knownProfiles) == 0 && goos != "windows" && runtime.GOOS != "windows" {
 		// No known profiles, try a migration.
+		pm.dlogf("no known profiles; trying to migrate from legacy prefs")
 		if err := pm.migrateFromLegacyPrefs(); err != nil {
 			return nil, err
 		}
@@ -573,11 +586,13 @@ func (pm *profileManager) migrateFromLegacyPrefs() error {
 		metricMigrationError.Add(1)
 		return fmt.Errorf("load legacy prefs: %w", err)
 	}
+	pm.dlogf("loaded legacy preferences; sentinel=%q", sentinel)
 	if err := pm.SetPrefs(prefs); err != nil {
 		metricMigrationError.Add(1)
 		return fmt.Errorf("migrating _daemon profile: %w", err)
 	}
 	pm.completeMigration(sentinel)
+	pm.dlogf("completed legacy preferences migration with sentinel=%q", sentinel)
 	metricMigrationSuccess.Add(1)
 	return nil
 }

ipn/ipnlocal/profiles_windows.go

@@ -40,6 +40,7 @@ func legacyPrefsDir(uid ipn.WindowsUserID) (string, error) {
 func (pm *profileManager) loadLegacyPrefs() (string, ipn.PrefsView, error) {
 	userLegacyPrefsDir, err := legacyPrefsDir(pm.currentUserID)
 	if err != nil {
+		pm.dlogf("no legacy preferences directory for %q: %v", pm.currentUserID, err)
 		return "", ipn.PrefsView{}, err
 	}
 
@@ -47,14 +48,17 @@ func (pm *profileManager) loadLegacyPrefs() (string, ipn.PrefsView, error) {
 	// verify that migration sentinel is not present
 	_, err = os.Stat(migrationSentinel)
 	if err == nil {
+		pm.dlogf("migration sentinel %q already exists", migrationSentinel)
 		return "", ipn.PrefsView{}, errAlreadyMigrated
 	}
 	if !os.IsNotExist(err) {
+		pm.dlogf("os.Stat(%q) = %v", migrationSentinel, err)
 		return "", ipn.PrefsView{}, err
 	}
 
 	prefsPath := filepath.Join(userLegacyPrefsDir, legacyPrefsFile+legacyPrefsExt)
 	prefs, err := ipn.LoadPrefs(prefsPath)
+	pm.dlogf("ipn.LoadPrefs(%q) = %v, %v", prefsPath, prefs, err)
 	if errors.Is(err, fs.ErrNotExist) {
 		return "", ipn.PrefsView{}, errAlreadyMigrated
 	}