internal/repos: Add debug logs (#44020)

Also wrap errors in some places.

Co-authored-by: Alex Ostrikov <[email protected]>
Co-authored-by: Ryan Slade <[email protected]>

Author: 3 people

internal/repos/github.go

@@ -298,8 +298,11 @@ func (s *GitHubSource) ListRepos(ctx context.Context, results chan SourceResult)
 			results <- SourceResult{Source: s, Err: res.err}
 			continue
 		}
+
+		s.logger.Debug("unfiltered", log.String("repo", res.repo.NameWithOwner))
 		if !seen[res.repo.DatabaseID] && !s.excludes(res.repo) {
 			results <- SourceResult{Source: s, Repo: s.makeRepo(res.repo)}
+			s.logger.Debug("sent to result", log.String("repo", res.repo.NameWithOwner))
 			seen[res.repo.DatabaseID] = true
 		}
 	}
@@ -567,13 +570,13 @@ func (s *GitHubSource) listRepos(ctx context.Context, repos []string, results ch
 	for i := len(repos) - 1; i >= 0; i-- {
 		nameWithOwner := repos[i]
 		if err := ctx.Err(); err != nil {
-			results <- &githubResult{err: err}
+			results <- &githubResult{err: errors.Wrapf(err, "context error for repository: namewithOwner=%s", nameWithOwner)}
 			return
 		}
 
 		owner, name, err := github.SplitRepositoryNameWithOwner(nameWithOwner)
 		if err != nil {
-			results <- &githubResult{err: errors.New("Invalid GitHub repository: nameWithOwner=" + nameWithOwner)}
+			results <- &githubResult{err: errors.Newf("Invalid GitHub repository: nameWithOwner=%s", nameWithOwner)}
 			return
 		}
 		var repo *github.Repository
@@ -941,6 +944,7 @@ func (s *GitHubSource) fetchAllRepositoriesInBatches(ctx context.Context, result
 
 	// Admins normally add to end of lists, so end of list most likely has new
 	// repos => stream them first.
+	s.logger.Debug("fetching list of repos", log.Int("len", len(s.config.Repos)))
 	for end := len(s.config.Repos); end > 0; end -= batchSize {
 		if err := ctx.Err(); err != nil {
 			return err
@@ -954,17 +958,22 @@ func (s *GitHubSource) fetchAllRepositoriesInBatches(ctx context.Context, result
 
 		repos, err := s.v4Client.GetReposByNameWithOwner(ctx, batch...)
 		if err != nil {
-			return err
+			return errors.Wrap(err, "GetReposByNameWithOwner failed")
 		}
 
 		s.logger.Debug("github sync: GetReposByNameWithOwner", log.Strings("repos", batch))
 		for _, r := range repos {
 			if err := ctx.Err(); err != nil {
+				if r != nil {
+					err = errors.Wrapf(err, "context error for repository: %s", r.NameWithOwner)
+				}
+
 				results <- &githubResult{err: err}
 				return err
 			}
 
 			results <- &githubResult{repo: r}
+			s.logger.Debug("sent repo to result", log.String("repo", fmt.Sprintf("%+v", r)))
 		}
 	}
 

internal/repos/scheduler.go

@@ -36,6 +36,8 @@ func RunScheduler(ctx context.Context, logger log.Logger, scheduler *UpdateSched
 		stop context.CancelFunc
 	)
 
+	logger = logger.Scoped("RunScheduler", "git fetch scheduler")
+
 	conf.Watch(func() {
 		c := conf.Get()
 
@@ -48,6 +50,7 @@ func RunScheduler(ctx context.Context, logger log.Logger, scheduler *UpdateSched
 			return
 		}
 
+		logger.Debug("config changed")
 		if stop != nil {
 			stop()
 			logger.Info("stopped previous scheduler")

internal/repos/syncer.go

@@ -307,50 +307,60 @@ func (rm ReposModified) ReposModified(modified types.RepoModified) types.Repos {
 // sync in the background vs block and call s.syncRepo synchronously.
 func (s *Syncer) SyncRepo(ctx context.Context, name api.RepoName, background bool) (repo *types.Repo, err error) {
 	logger := s.Logger.With(log.String("name", string(name)), log.Bool("background", background))
+
+	logger.Debug("SyncRepo started")
+
 	tr, ctx := trace.New(ctx, "Syncer.SyncRepo", string(name))
 	defer tr.Finish()
 
 	repo, err = s.Store.RepoStore().GetByName(ctx, name)
 	if err != nil && !errcode.IsNotFound(err) {
-		return nil, err
+		return nil, errors.Wrapf(err, "GetByName failed for %q", name)
 	}
 
 	codehost := extsvc.CodeHostOf(name, extsvc.PublicCodeHosts...)
 	if codehost == nil {
 		if repo != nil {
 			return repo, nil
 		}
+
+		logger.Debug("no associated code host found, skipping")
 		return nil, &database.RepoNotFoundErr{Name: name}
 	}
 
 	if repo != nil {
 		// Only public repos can be individually synced on sourcegraph.com
 		if repo.Private {
+			logger.Debug("repo is private, skipping")
 			return nil, &database.RepoNotFoundErr{Name: name}
 		}
 		// Don't sync the repo if it's been updated in the past 1 minute.
 		if s.Now().Sub(repo.UpdatedAt) < time.Minute {
+			logger.Debug("repo updated recently, skipping")
 			return repo, nil
 		}
 	}
 
 	if background && repo != nil {
+		logger.Debug("starting background sync in goroutine")
 		go func() {
 			ctx, cancel := context.WithTimeout(context.Background(), 3*time.Minute)
 			defer cancel()
 
 			// We don't care about the return value here, but we still want to ensure that
 			// only one is in flight at a time.
-			_, err, shared := s.syncGroup.Do(string(name), func() (any, error) {
+			updatedRepo, err, shared := s.syncGroup.Do(string(name), func() (any, error) {
 				return s.syncRepo(ctx, codehost, name, repo)
 			})
+			logger.Debug("syncGroup completed", log.String("updatedRepo", fmt.Sprintf("%v", updatedRepo.(*types.Repo))))
 			if err != nil {
 				logger.Error("SyncRepo", log.Error(err), log.Bool("shared", shared))
 			}
 		}()
 		return repo, nil
 	}
 
+	logger.Debug("starting foreground sync")
 	updatedRepo, err, shared := s.syncGroup.Do(string(name), func() (any, error) {
 		return s.syncRepo(ctx, codehost, name, repo)
 	})
@@ -396,7 +406,7 @@ func (s *Syncer) syncRepo(
 
 	src, err := s.Sourcer(ctx, svc)
 	if err != nil {
-		return nil, err
+		return nil, errors.Wrap(err, "failed to retrieve Sourcer")
 	}
 
 	rg, ok := src.(RepoGetter)
@@ -411,6 +421,7 @@ func (s *Syncer) syncRepo(
 
 	if stored != nil {
 		defer func() {
+			s.Logger.Debug("deferred deletable repo check")
 			if isDeleteableRepoError(err) {
 				err2 := s.Store.DeleteExternalServiceRepo(ctx, svc, stored.ID)
 				if err2 != nil {
@@ -422,17 +433,19 @@ func (s *Syncer) syncRepo(
 						log.Error(err2),
 					)
 				}
+				s.Logger.Debug("external service repo deleted", log.Int32("deleted ID", int32(stored.ID)))
 				s.notifyDeleted(ctx, stored.ID)
 			}
 		}()
 	}
 
 	repo, err = rg.GetRepo(ctx, path)
 	if err != nil {
-		return nil, err
+		return nil, errors.Wrapf(err, "failed to get repo with path: %q", path)
 	}
 
 	if repo.Private {
+		s.Logger.Debug("repo is private, skipping")
 		return nil, &database.RepoNotFoundErr{Name: name}
 	}
 
@@ -646,6 +659,7 @@ func (s *Syncer) SyncExternalService(
 
 	results := make(chan SourceResult)
 	go func() {
+		s.Logger.Debug("listing repos asynchronously")
 		src.ListRepos(ctx, results)
 		close(results)
 	}()
@@ -676,6 +690,8 @@ func (s *Syncer) SyncExternalService(
 	// Insert or update repos as they are sourced. Keep track of what was seen so we
 	// can remove anything else at the end.
 	for res := range results {
+		logger.Debug("received result", log.String("repo", fmt.Sprintf("%v", res)))
+
 		if err := progressRecorder(ctx, syncProgress, false); err != nil {
 			logger.Warn("recording sync progress", log.Error(err))
 		}
@@ -839,15 +855,20 @@ func (s *Syncer) sync(ctx context.Context, svc *types.ExternalService, sourced *
 		observeDiff(d)
 		// We must commit the transaction before publishing to s.Synced
 		// so that gitserver finds the repo in the database.
+
+		s.Logger.Debug("committing transaction")
 		err = tx.Done(err)
 		if err != nil {
+			s.Logger.Warn("failed to commit transaction", log.Error(err))
 			return
 		}
 
 		if s.Synced != nil && d.Len() > 0 {
 			select {
 			case <-ctx.Done():
+				s.Logger.Debug("sync context done")
 			case s.Synced <- d:
+				s.Logger.Debug("diff synced")
 			}
 		}
 	}()
@@ -865,6 +886,8 @@ func (s *Syncer) sync(ctx context.Context, svc *types.ExternalService, sourced *
 
 	switch len(stored) {
 	case 2: // Existing repo with a naming conflict
+		s.Logger.Debug("naming conflict")
+
 		// Pick this sourced repo to own the name by deleting the other repo. If it still exists, it'll have a different
 		// name when we source it from the same code host, and it will be re-created.
 		var conflicting, existing *types.Repo
@@ -884,8 +907,10 @@ func (s *Syncer) sync(ctx context.Context, svc *types.ExternalService, sourced *
 		// We fallthrough to the next case after removing the conflicting repo in order to update
 		// the winner (i.e. existing). This works because we mutate stored to contain it, which the case expects.
 		stored = types.Repos{existing}
+		s.Logger.Debug("retrieved stored repo, falling through", log.String("stored", fmt.Sprintf("%v", stored)))
 		fallthrough
 	case 1: // Existing repo, update.
+		s.Logger.Debug("exisitng repo")
 		modified := stored[0].Update(sourced)
 		if modified == types.RepoUnmodified {
 			d.Unmodified = append(d.Unmodified, stored[0])
@@ -898,7 +923,9 @@ func (s *Syncer) sync(ctx context.Context, svc *types.ExternalService, sourced *
 
 		*sourced = *stored[0]
 		d.Modified = append(d.Modified, RepoModified{Repo: stored[0], Modified: modified})
+		s.Logger.Debug("appended to modified repos")
 	case 0: // New repo, create.
+		s.Logger.Debug("new repo")
 		if !svc.IsSiteOwned() { // enforce user and org repo limits
 			siteAdded, err := tx.CountNamespacedRepos(ctx, 0, 0)
 			if err != nil {
@@ -931,10 +958,12 @@ func (s *Syncer) sync(ctx context.Context, svc *types.ExternalService, sourced *
 		}
 
 		d.Added = append(d.Added, sourced)
+		s.Logger.Debug("appended to added repos")
 	default: // Impossible since we have two separate unique constraints on name and external repo spec
 		panic("unreachable")
 	}
 
+	s.Logger.Debug("completed")
 	return d, nil
 }