diff --git a/cmd/zoekt-sourcegraph-indexserver/cleanup.go b/cmd/zoekt-sourcegraph-indexserver/cleanup.go index e8282e73..27097cac 100644 --- a/cmd/zoekt-sourcegraph-indexserver/cleanup.go +++ b/cmd/zoekt-sourcegraph-indexserver/cleanup.go @@ -2,7 +2,6 @@ package main import ( "fmt" - "log" "os" "os/exec" "path/filepath" @@ -31,7 +30,7 @@ func cleanup(indexDir string, repos []uint32, now time.Time, shardMerging bool) start := time.Now() trashDir := filepath.Join(indexDir, ".trash") if err := os.MkdirAll(trashDir, 0o755); err != nil { - log.Printf("failed to create trash dir: %v", err) + errorLog.Printf("failed to create trash dir: %v", err) } trash := getShards(trashDir) @@ -46,7 +45,7 @@ func cleanup(indexDir string, repos []uint32, now time.Time, shardMerging bool) if shard.ModTime.Before(minAge) { old = true } else if shard.ModTime.After(now) { - debug.Printf("trashed shard %s has timestamp in the future, reseting to now", shard.Path) + debugLog.Printf("trashed shard %s has timestamp in the future, reseting to now", shard.Path) _ = os.Chtimes(shard.Path, now, now) } } @@ -55,7 +54,7 @@ func cleanup(indexDir string, repos []uint32, now time.Time, shardMerging bool) continue } - log.Printf("removing old shards from trash for %v", repo) + infoLog.Printf("removing old shards from trash for %v", repo) removeAll(shards...) delete(trash, repo) } @@ -89,7 +88,7 @@ func cleanup(indexDir string, repos []uint32, now time.Time, shardMerging bool) for _, shard := range shards { paths = append(paths, filepath.Base(shard.Path)) } - log.Printf("removing shards for %v due to multiple repository names: %s", repo, strings.Join(paths, " ")) + infoLog.Printf("removing shards for %v due to multiple repository names: %s", repo, strings.Join(paths, " ")) // We may be in both normal and compound shards in this case. First // tombstone the compound shards so we don't just rm them. @@ -117,16 +116,16 @@ func cleanup(indexDir string, repos []uint32, now time.Time, shardMerging bool) delete(index, repo) if shards, ok := trash[repo]; ok { - log.Printf("restoring shards from trash for %v", repo) + infoLog.Printf("restoring shards from trash for %v", repo) moveAll(indexDir, shards) continue } if s, ok := tombtones[repo]; ok { - log.Printf("removing tombstone for %v", repo) + infoLog.Printf("removing tombstone for %v", repo) err := zoekt.UnsetTombstone(s.Path, repo) if err != nil { - log.Printf("error removing tombstone for %v: %s", repo, err) + errorLog.Printf("error removing tombstone for %v: %s", repo, err) } } } @@ -150,16 +149,16 @@ func cleanup(indexDir string, repos []uint32, now time.Time, shardMerging bool) // the files now since cleanup runs with a global lock (no indexing jobs // running at the same time). if failures, err := filepath.Glob(filepath.Join(indexDir, "*.tmp")); err != nil { - log.Printf("Glob: %v", err) + errorLog.Printf("Glob: %v", err) } else { for _, f := range failures { st, err := os.Stat(f) if err != nil { - log.Printf("Stat(%q): %v", f, err) + errorLog.Printf("Stat(%q): %v", f, err) continue } if !st.IsDir() { - log.Printf("removing tmp file: %s", f) + infoLog.Printf("removing tmp file: %s", f) os.Remove(f) } } @@ -179,7 +178,7 @@ type shard struct { func getShards(dir string) map[uint32][]shard { d, err := os.Open(dir) if err != nil { - debug.Printf("failed to getShards: %s", dir) + debugLog.Printf("failed to getShards: %s", dir) return nil } defer d.Close() @@ -191,7 +190,7 @@ func getShards(dir string) map[uint32][]shard { path := filepath.Join(dir, n) fi, err := os.Stat(path) if err != nil { - debug.Printf("stat failed: %v", err) + debugLog.Printf("stat failed: %v", err) continue } if fi.IsDir() || filepath.Ext(path) != ".zoekt" { @@ -200,7 +199,7 @@ func getShards(dir string) map[uint32][]shard { repos, _, err := zoekt.ReadMetadataPathAlive(path) if err != nil { - debug.Printf("failed to read shard: %v", err) + debugLog.Printf("failed to read shard: %v", err) continue } @@ -260,7 +259,7 @@ var incompleteRE = regexp.MustCompile(`\.zoekt[0-9]+(\.\w+)?$`) func removeIncompleteShards(dir string) { d, err := os.Open(dir) if err != nil { - debug.Printf("failed to removeIncompleteShards: %s", dir) + debugLog.Printf("failed to removeIncompleteShards: %s", dir) return } defer d.Close() @@ -270,9 +269,9 @@ func removeIncompleteShards(dir string) { if incompleteRE.MatchString(n) { path := filepath.Join(dir, n) if err := os.Remove(path); err != nil { - debug.Printf("failed to remove incomplete shard %s: %v", path, err) + debugLog.Printf("failed to remove incomplete shard %s: %v", path, err) } else { - debug.Printf("cleaned up incomplete shard %s", path) + debugLog.Printf("cleaned up incomplete shard %s", path) } } } @@ -288,11 +287,11 @@ func removeAll(shards ...shard) { for _, shard := range shards { paths, err := zoekt.IndexFilePaths(shard.Path) if err != nil { - debug.Printf("failed to remove shard %s: %v", shard.Path, err) + debugLog.Printf("failed to remove shard %s: %v", shard.Path, err) } for _, p := range paths { if err := os.Remove(p); err != nil { - debug.Printf("failed to remove shard file %s: %v", p, err) + debugLog.Printf("failed to remove shard file %s: %v", p, err) } } } @@ -302,7 +301,7 @@ func moveAll(dstDir string, shards []shard) { for i, shard := range shards { paths, err := zoekt.IndexFilePaths(shard.Path) if err != nil { - log.Printf("failed to stat shard paths, deleting all shards for %s: %v", shard.RepoName, err) + errorLog.Printf("failed to stat shard paths, deleting all shards for %s: %v", shard.RepoName, err) removeAll(shards...) return } @@ -316,7 +315,7 @@ func moveAll(dstDir string, shards []shard) { // HACK we do not yet support tombstones in compound shard. So we avoid // needing to deal with it by always deleting the whole compound shard. if strings.HasPrefix(filepath.Base(shard.Path), "compound-") { - log.Printf("HACK removing compound shard since we don't support tombstoning: %s", shard.Path) + infoLog.Printf("HACK removing compound shard since we don't support tombstoning: %s", shard.Path) removeAll(shard) continue } @@ -331,7 +330,7 @@ func moveAll(dstDir string, shards []shard) { } if err != nil { - log.Printf("failed to move shard, deleting all shards for %s: %v", shard.RepoName, err) + errorLog.Printf("failed to move shard, deleting all shards for %s: %v", shard.RepoName, err) removeAll(dstShard) // some files may have moved to dst removeAll(shards...) return @@ -369,7 +368,7 @@ func maybeSetTombstone(shards []shard, repoID uint32) bool { } if err := zoekt.SetTombstone(shards[0].Path, repoID); err != nil { - log.Printf("error setting tombstone for %d in shard %s: %s. Removing shard\n", repoID, shards[0].Path, err) + errorLog.Printf("error setting tombstone for %d in shard %s: %s. Removing shard\n", repoID, shards[0].Path, err) _ = os.Remove(shards[0].Path) } return true @@ -409,7 +408,7 @@ func (s *Server) vacuum() { path := filepath.Join(s.IndexDir, fn) info, err := os.Stat(path) if err != nil { - log.Printf("vacuum stat failed: %v", err) + errorLog.Printf("vacuum stat failed: %v", err) continue } @@ -422,9 +421,9 @@ func (s *Server) vacuum() { }) if err != nil { - log.Printf("failed to explode compound shard: shard=%s out=%s err=%s", path, string(b), err) + errorLog.Printf("failed to explode compound shard: shard=%s out=%s err=%s", path, string(b), err) } - log.Printf("exploded compound shard: shard=%s", path) + infoLog.Printf("exploded compound shard: shard=%s", path) continue } @@ -433,7 +432,7 @@ func (s *Server) vacuum() { }) if err != nil { - log.Printf("error while removing tombstones in %s: %s", path, err) + errorLog.Printf("error while removing tombstones in %s: %s", path, err) } } } diff --git a/cmd/zoekt-sourcegraph-indexserver/debug.go b/cmd/zoekt-sourcegraph-indexserver/debug.go index c407e6a3..302f910c 100644 --- a/cmd/zoekt-sourcegraph-indexserver/debug.go +++ b/cmd/zoekt-sourcegraph-indexserver/debug.go @@ -6,7 +6,6 @@ import ( "context" "flag" "fmt" - "log" "strconv" "github.com/peterbourgon/ff/v3/ffcli" @@ -35,7 +34,7 @@ func debugIndex() *ffcli.Command { return err } msg, err := s.forceIndex(uint32(id)) - log.Println(msg) + infoLog.Println(msg) if err != nil { return err } diff --git a/cmd/zoekt-sourcegraph-indexserver/index.go b/cmd/zoekt-sourcegraph-indexserver/index.go index 3bcf86a0..fdd3ead8 100644 --- a/cmd/zoekt-sourcegraph-indexserver/index.go +++ b/cmd/zoekt-sourcegraph-indexserver/index.go @@ -7,7 +7,6 @@ import ( "errors" "fmt" "io" - "log" "net/url" "os" "os/exec" @@ -321,7 +320,7 @@ func fetchRepo(ctx context.Context, gitDir string, o *indexArgs, c gitIndexConfi name := o.BuildOptions().RepositoryDescription.Name id := o.BuildOptions().RepositoryDescription.ID - log.Printf("delta build: failed to prepare delta build for %q (ID %d): failed to fetch both latest and prior commits: %s", name, id, err) + errorLog.Printf("delta build: failed to prepare delta build for %q (ID %d): failed to fetch both latest and prior commits: %s", name, id, err) err = fetchOnlyLatestCommits() if err != nil { return err diff --git a/cmd/zoekt-sourcegraph-indexserver/main.go b/cmd/zoekt-sourcegraph-indexserver/main.go index cf38fa21..5c7d05f2 100644 --- a/cmd/zoekt-sourcegraph-indexserver/main.go +++ b/cmd/zoekt-sourcegraph-indexserver/main.go @@ -215,7 +215,11 @@ type Server struct { timeout time.Duration } -var debug = log.New(io.Discard, "", log.LstdFlags) +var ( + debugLog = log.New(io.Discard, "[DEBUG] ", log.LstdFlags) + infoLog = log.New(os.Stderr, "[INFO] ", log.LstdFlags) + errorLog = log.New(os.Stderr, "[ERROR] ", log.LstdFlags) +) // our index commands should output something every 100mb they process. // @@ -263,12 +267,12 @@ func (s *Server) loggedRun(tr trace.Trace, cmd *exec.Cmd) (err error) { // Periodically check if we have had output. If not kill the process. if out.Len() != lastLen { lastLen = out.Len() - log.Printf("still running %s", cmd.Args) + infoLog.Printf("still running %s", cmd.Args) } else { // Send quit (C-\) first so we get a stack dump. - log.Printf("no output for %s, quitting %s", noOutputTimeout, cmd.Args) + infoLog.Printf("no output for %s, quitting %s", noOutputTimeout, cmd.Args) if err := cmd.Process.Signal(unix.SIGQUIT); err != nil { - log.Println("quit failed:", err) + errorLog.Println("quit failed:", err) } // send sigkill if still running in 10s @@ -276,9 +280,9 @@ func (s *Server) loggedRun(tr trace.Trace, cmd *exec.Cmd) (err error) { } case <-kill: - log.Printf("still running, killing %s", cmd.Args) + infoLog.Printf("still running, killing %s", cmd.Args) if err := cmd.Process.Kill(); err != nil { - log.Println("kill failed:", err) + errorLog.Println("kill failed:", err) } case err := <-errC: @@ -334,23 +338,23 @@ func (s *Server) Run() { // "pkill -SIGUSR1 zoekt-sourcegra" for range jitterTicker(s.Interval, unix.SIGUSR1) { if b, err := os.ReadFile(filepath.Join(s.IndexDir, pauseFileName)); err == nil { - log.Printf("indexserver manually paused via PAUSE file: %s", string(bytes.TrimSpace(b))) + infoLog.Printf("indexserver manually paused via PAUSE file: %s", string(bytes.TrimSpace(b))) continue } repos, err := s.Sourcegraph.List(context.Background(), listIndexed(s.IndexDir)) if err != nil { - log.Printf("error listing repos: %s", err) + errorLog.Printf("error listing repos: %s", err) continue } - debug.Printf("updating index queue with %d repositories", len(repos.IDs)) + debugLog.Printf("updating index queue with %d repositories", len(repos.IDs)) // Stop indexing repos we don't need to track anymore removed := s.queue.MaybeRemoveMissing(repos.IDs) metricNumStoppedTrackingTotal.Add(float64(len(removed))) if len(removed) > 0 { - log.Printf("stopped tracking %d repositories: %s", len(removed), formatListUint32(removed, 5)) + infoLog.Printf("stopped tracking %d repositories: %s", len(removed), formatListUint32(removed, 5)) } cleanupDone := make(chan struct{}) @@ -450,7 +454,7 @@ func (s *Server) processQueue() { metricIndexingDelay.WithLabelValues(string(state), repoNameForMetric(opts.Name)).Observe(indexDelay.Seconds()) if err != nil { - log.Printf("error indexing %s: %s", args.String(), err) + errorLog.Printf("error indexing %s: %s", args.String(), err) } switch state { @@ -468,7 +472,7 @@ func (s *Server) processQueue() { sglog.Duration("index_delay", indexDelay), ) case indexStateSuccessMeta: - log.Printf("updated meta %s in %v", args.String(), elapsed) + infoLog.Printf("updated meta %s in %v", args.String(), elapsed) } s.queue.SetIndexed(opts, state) }) @@ -477,7 +481,7 @@ func (s *Server) processQueue() { // Someone else is processing the repository. We can just skip this job // since the repository will be added back to the queue and we will // converge to the correct behaviour. - debug.Printf("index job for repository already running: %s", args) + debugLog.Printf("index job for repository already running: %s", args) continue } } @@ -593,25 +597,25 @@ func (s *Server) Index(args *indexArgs) (state indexState, err error) { switch incrementalState { case build.IndexStateEqual: - debug.Printf("%s index already up to date. Shard=%s", args.String(), fn) + debugLog.Printf("%s index already up to date. Shard=%s", args.String(), fn) return indexStateNoop, nil case build.IndexStateMeta: - log.Printf("updating index.meta %s", args.String()) + infoLog.Printf("updating index.meta %s", args.String()) // TODO(stefan) handle mergeMeta for tenant id. if err := mergeMeta(bo); err != nil { - log.Printf("falling back to full update: failed to update index.meta %s: %s", args.String(), err) + errorLog.Printf("falling back to full update: failed to update index.meta %s: %s", args.String(), err) } else { return indexStateSuccessMeta, nil } case build.IndexStateCorrupt: - log.Printf("falling back to full update: corrupt index: %s", args.String()) + infoLog.Printf("falling back to full update: corrupt index: %s", args.String()) } } - log.Printf("updating index %s reason=%s", args.String(), reason) + infoLog.Printf("updating index %s reason=%s", args.String(), reason) metricIndexingTotal.Inc() c := gitIndexConfig{ @@ -906,7 +910,7 @@ func (s *Server) handleDebugList(w http.ResponseWriter, r *http.Request) { } _, err = fmt.Fprintf(tw, "%d\t%s\n", id, name) if err != nil { - debug.Printf("handleDebugList: %s\n", err.Error()) + debugLog.Printf("handleDebugList: %s\n", err.Error()) } } s.queue.mu.Unlock() @@ -969,7 +973,7 @@ func (s *Server) handleDebugIndexed(w http.ResponseWriter, r *http.Request) { } _, err = fmt.Fprintf(tw, "%d\t%s\n", id, name) if err != nil { - debug.Printf("handleDebugIndexed: %s\n", err.Error()) + debugLog.Printf("handleDebugIndexed: %s\n", err.Error()) } } s.queue.mu.Unlock() @@ -1207,7 +1211,7 @@ func joinStringSet(set map[string]struct{}, sep string) string { func setCompoundShardCounter(indexDir string) { fns, err := filepath.Glob(filepath.Join(indexDir, "compound-*.zoekt")) if err != nil { - log.Printf("setCompoundShardCounter: %s\n", err) + errorLog.Printf("setCompoundShardCounter: %s\n", err) return } metricNumberCompoundShards.Set(float64(len(fns))) @@ -1298,7 +1302,7 @@ func startServer(conf rootConfig) error { s.addDebugHandlers(mux) go func() { - debug.Printf("serving HTTP on %s", conf.listen) + debugLog.Printf("serving HTTP on %s", conf.listen) log.Fatal(http.ListenAndServe(conf.listen, mux)) }() @@ -1330,10 +1334,10 @@ func startServer(conf rootConfig) error { if err := os.Chmod(socket, 0o777); err != nil { return fmt.Errorf("failed to change permission of socket %s: %w", socket, err) } - debug.Printf("serving HTTP on %s", socket) + debugLog.Printf("serving HTTP on %s", socket) return http.Serve(l, mux) } - debug.Print(serveHTTPOverSocket()) + debugLog.Print(serveHTTPOverSocket()) }() } @@ -1392,34 +1396,34 @@ func newServer(conf rootConfig) (*Server, error) { } if srcLogLevelIsDebug() { - debug = log.New(os.Stderr, "", log.LstdFlags) + debugLog.SetOutput(os.Stderr) } reposWithSeparateIndexingMetrics = getEnvWithDefaultEmptySet("INDEXING_METRICS_REPOS_ALLOWLIST") if len(reposWithSeparateIndexingMetrics) > 0 { - debug.Printf("capturing separate indexing metrics for: %s", joinStringSet(reposWithSeparateIndexingMetrics, ", ")) + debugLog.Printf("capturing separate indexing metrics for: %s", joinStringSet(reposWithSeparateIndexingMetrics, ", ")) } deltaBuildRepositoriesAllowList := getEnvWithDefaultEmptySet("DELTA_BUILD_REPOS_ALLOWLIST") if len(deltaBuildRepositoriesAllowList) > 0 { - debug.Printf("using delta shard builds for: %s", joinStringSet(deltaBuildRepositoriesAllowList, ", ")) + debugLog.Printf("using delta shard builds for: %s", joinStringSet(deltaBuildRepositoriesAllowList, ", ")) } deltaShardNumberFallbackThreshold := getEnvWithDefaultUint64("DELTA_SHARD_NUMBER_FALLBACK_THRESHOLD", 150) if deltaShardNumberFallbackThreshold > 0 { - debug.Printf("setting delta shard fallback threshold to %d shard(s)", deltaShardNumberFallbackThreshold) + debugLog.Printf("setting delta shard fallback threshold to %d shard(s)", deltaShardNumberFallbackThreshold) } else { - debug.Printf("disabling delta build fallback behavior - delta builds will be performed regardless of the number of preexisting shards") + debugLog.Printf("disabling delta build fallback behavior - delta builds will be performed regardless of the number of preexisting shards") } reposShouldSkipSymbolsCalculation := getEnvWithDefaultEmptySet("SKIP_SYMBOLS_REPOS_ALLOWLIST") if len(reposShouldSkipSymbolsCalculation) > 0 { - debug.Printf("skipping generating symbols metadata for: %s", joinStringSet(reposShouldSkipSymbolsCalculation, ", ")) + debugLog.Printf("skipping generating symbols metadata for: %s", joinStringSet(reposShouldSkipSymbolsCalculation, ", ")) } indexingTimeout := getEnvWithDefaultDuration("INDEXING_TIMEOUT", defaultIndexingTimeout) if indexingTimeout != defaultIndexingTimeout { - debug.Printf("using configured indexing timeout: %s", indexingTimeout) + debugLog.Printf("using configured indexing timeout: %s", indexingTimeout) } var sg Sourcegraph diff --git a/cmd/zoekt-sourcegraph-indexserver/main_test.go b/cmd/zoekt-sourcegraph-indexserver/main_test.go index aebfa6fb..e86bf953 100644 --- a/cmd/zoekt-sourcegraph-indexserver/main_test.go +++ b/cmd/zoekt-sourcegraph-indexserver/main_test.go @@ -205,6 +205,9 @@ func TestMain(m *testing.M) { level := sglog.LevelInfo if !testing.Verbose() { log.SetOutput(io.Discard) + debugLog.SetOutput(io.Discard) + infoLog.SetOutput(io.Discard) + errorLog.SetOutput(io.Discard) level = sglog.LevelNone } diff --git a/cmd/zoekt-sourcegraph-indexserver/merge.go b/cmd/zoekt-sourcegraph-indexserver/merge.go index 2d174411..ca70ddd2 100644 --- a/cmd/zoekt-sourcegraph-indexserver/merge.go +++ b/cmd/zoekt-sourcegraph-indexserver/merge.go @@ -2,7 +2,6 @@ package main import ( "bytes" - "log" "os" "os/exec" "path/filepath" @@ -59,7 +58,7 @@ func (s *Server) merge(mergeCmd func(args ...string) *exec.Cmd) { // Guard against the user triggering competing merge jobs with the debug // command. if !mergeRunning.CompareAndSwap(false, true) { - log.Printf("merge already running") + infoLog.Printf("merge already running") return } defer mergeRunning.Store(false) @@ -74,14 +73,14 @@ func (s *Server) merge(mergeCmd func(args ...string) *exec.Cmd) { next = false s.muIndexDir.Global(func() { candidates, excluded := loadCandidates(s.IndexDir, s.mergeOpts) - log.Printf("loadCandidates: candidates=%d excluded=%d", len(candidates), excluded) + infoLog.Printf("loadCandidates: candidates=%d excluded=%d", len(candidates), excluded) c := pickCandidates(candidates, s.mergeOpts.targetSizeBytes) if len(c.shards) <= 1 { - log.Printf("could not find enough shards to build a compound shard") + infoLog.Printf("could not find enough shards to build a compound shard") return } - log.Printf("start merging: shards=%d total_size=%.2fMiB", len(c.shards), float64(c.size)/(1024*1024)) + infoLog.Printf("start merging: shards=%d total_size=%.2fMiB", len(c.shards), float64(c.size)/(1024*1024)) var paths []string for _, p := range c.shards { @@ -103,11 +102,11 @@ func (s *Server) merge(mergeCmd func(args ...string) *exec.Cmd) { durationSeconds := time.Since(start).Seconds() metricShardMergingDuration.WithLabelValues(strconv.FormatBool(err != nil)).Observe(durationSeconds) if err != nil { - log.Printf("error merging shards: stdout=%s, stderr=%s, durationSeconds=%.2f err=%s", stdoutBuf.String(), stderrBuf.String(), durationSeconds, err) + errorLog.Printf("error merging shards: stdout=%s, stderr=%s, durationSeconds=%.2f err=%s", stdoutBuf.String(), stderrBuf.String(), durationSeconds, err) return } - log.Printf("finished merging: shard=%s durationSeconds=%.2f", stdoutBuf.String(), durationSeconds) + infoLog.Printf("finished merging: shard=%s durationSeconds=%.2f", stdoutBuf.String(), durationSeconds) next = true }) @@ -127,7 +126,7 @@ func loadCandidates(dir string, opts mergeOpts) ([]candidate, int) { d, err := os.Open(dir) if err != nil { - debug.Printf("failed to load candidates: %s", dir) + debugLog.Printf("failed to load candidates: %s", dir) return []candidate{}, excluded } defer d.Close() @@ -139,7 +138,7 @@ func loadCandidates(dir string, opts mergeOpts) ([]candidate, int) { fi, err := os.Stat(path) if err != nil { - debug.Printf("stat failed for %s: %s", n, err) + debugLog.Printf("stat failed for %s: %s", n, err) continue } @@ -206,7 +205,7 @@ func isExcluded(path string, fi os.FileInfo, opts mergeOpts) bool { repos, _, err := zoekt.ReadMetadataPath(path) if err != nil { - debug.Printf("failed to load metadata for %s\n", fi.Name()) + debugLog.Printf("failed to load metadata for %s\n", fi.Name()) return true } diff --git a/cmd/zoekt-sourcegraph-indexserver/owner.go b/cmd/zoekt-sourcegraph-indexserver/owner.go index 572ac8a7..def1f48a 100644 --- a/cmd/zoekt-sourcegraph-indexserver/owner.go +++ b/cmd/zoekt-sourcegraph-indexserver/owner.go @@ -53,7 +53,7 @@ func (o *ownerChecker) Init() error { if err := o.Check(); errors.Is(err, fs.ErrNotExist) { // do nothing, first run so we just write out the file } else if errors.As(err, &ownerErr) { - debug.Printf("WARN: detected a change in ownership at startup. You can ignore this if you only have one zoekt replica: %s", err) + debugLog.Printf("WARN: detected a change in ownership at startup. You can ignore this if you only have one zoekt replica: %s", err) } else if err != nil { return err } diff --git a/cmd/zoekt-sourcegraph-indexserver/queue.go b/cmd/zoekt-sourcegraph-indexserver/queue.go index 9a733d51..50dd0880 100644 --- a/cmd/zoekt-sourcegraph-indexserver/queue.go +++ b/cmd/zoekt-sourcegraph-indexserver/queue.go @@ -316,7 +316,7 @@ func (q *Queue) MaybeRemoveMissing(ids []uint32) []uint32 { // heuristically skip expensive work if sameSize { - debug.Printf("skipping MaybeRemoveMissing due to same size: %d", len(ids)) + debugLog.Printf("skipping MaybeRemoveMissing due to same size: %d", len(ids)) return nil } diff --git a/shards/shards.go b/shards/shards.go index 0991c582..4dcf0a62 100644 --- a/shards/shards.go +++ b/shards/shards.go @@ -303,13 +303,13 @@ func (tl *loader) load(keys ...string) { tl.ss.replace(chunk) } - log.Printf("loading %d shard(s): %s", len(keys), humanTruncateList(keys, 5)) + log.Printf("[INFO] loading %d shard(s): %s", len(keys), humanTruncateList(keys, 5)) lastProgress := time.Now() for i, key := range keys { // If taking a while to start-up occasionally give a progress message if time.Since(lastProgress) > 5*time.Second { - log.Printf("still need to load %d shards...", len(keys)-i) + log.Printf("[INFO] still need to load %d shards...", len(keys)-i) lastProgress = time.Now() publishLoaded() @@ -325,7 +325,7 @@ func (tl *loader) load(keys ...string) { shard, err := loadShard(key) if err != nil { metricShardsLoadFailedTotal.Inc() - log.Printf("reloading: %s, err %v ", key, err) + log.Printf("[ERROR] reloading: %s, err %v ", key, err) return } metricShardsLoadedTotal.Inc() @@ -896,7 +896,7 @@ func searchOneShard(ctx context.Context, s zoekt.Searcher, q query.Q, opts *zoek defer func() { metricSearchShardRunning.Dec() if e := recover(); e != nil { - log.Printf("crashed shard: %s: %#v, %s", s, e, debug.Stack()) + log.Printf("[ERROR] crashed shard: %s: %#v, %s", s, e, debug.Stack()) if sr == nil { sr = &zoekt.SearchResult{} @@ -918,7 +918,7 @@ func listOneShard(ctx context.Context, s zoekt.Searcher, q query.Q, opts *zoekt. defer func() { metricListShardRunning.Dec() if r := recover(); r != nil { - log.Printf("crashed shard: %s: %s, %s", s.String(), r, debug.Stack()) + log.Printf("[ERROR] crashed shard: %s: %s, %s", s.String(), r, debug.Stack()) sink <- shardListResult{ &zoekt.RepoList{Crashes: 1}, nil, } @@ -1088,7 +1088,7 @@ func mkRankedShard(s zoekt.Searcher) *rankedShard { // rankedShard.repos being set. result, err := s.List(systemtenant.UnsafeCtx, &q, nil) if err != nil { - log.Printf("mkRankedShard(%s): failed to cache repository list: %v", s, err) + log.Printf("[ERROR] mkRankedShard(%s): failed to cache repository list: %v", s, err) return &rankedShard{Searcher: s} } diff --git a/shards/shards_test.go b/shards/shards_test.go index fb7a9ddd..c6bfbb60 100644 --- a/shards/shards_test.go +++ b/shards/shards_test.go @@ -17,8 +17,10 @@ package shards import ( "bytes" "context" + "flag" "fmt" "hash/fnv" + "io" "log" "math" "os" @@ -39,6 +41,14 @@ import ( "github.com/sourcegraph/zoekt/query" ) +func TestMain(m *testing.M) { + flag.Parse() + if !testing.Verbose() { + log.SetOutput(io.Discard) + } + os.Exit(m.Run()) +} + type crashSearcher struct{} func (s *crashSearcher) Search(ctx context.Context, q query.Q, opts *zoekt.SearchOptions) (*zoekt.SearchResult, error) { @@ -59,8 +69,10 @@ func (s *crashSearcher) String() string { return "crashSearcher" } func TestCrashResilience(t *testing.T) { out := &bytes.Buffer{} + oldOut := log.Writer() log.SetOutput(out) - defer log.SetOutput(os.Stderr) + defer log.SetOutput(oldOut) + ss := newShardedSearcher(2) ss.ranked.Store([]*rankedShard{{Searcher: &crashSearcher{}}}) diff --git a/shards/watcher.go b/shards/watcher.go index 16613f70..f64163f0 100644 --- a/shards/watcher.go +++ b/shards/watcher.go @@ -179,7 +179,7 @@ func (s *DirectoryWatcher) scan() error { } if len(toDrop) > 0 { - log.Printf("unloading %d shard(s): %s", len(toDrop), humanTruncateList(toDrop, 5)) + log.Printf("[INFO] unloading %d shard(s): %s", len(toDrop), humanTruncateList(toDrop, 5)) } s.loader.drop(toDrop...) @@ -244,7 +244,7 @@ func (s *DirectoryWatcher) watch() error { // Ignore ErrEventOverflow since we rely on the presence of events so // safe to ignore. if err != nil && err != fsnotify.ErrEventOverflow { - log.Println("watcher error:", err) + log.Println("[ERROR] watcher error:", err) } case <-s.quit: @@ -260,7 +260,7 @@ func (s *DirectoryWatcher) watch() error { defer close(s.stopped) for range signal { if err := s.scan(); err != nil { - log.Println("watcher error:", err) + log.Println("[ERROR] watcher error:", err) } } }()