fork of https://github.com/sourcegraph/zoekt
all: set severity hint in most log output (#871)
I was inspecting logs in GKE and it incorrectly categorized the severity
of nearly all logs from zoekt-webserver and zoekt-indexserver. This is a
hack to make it work better without putting in the bigger work of
migrating us to structured logging.
Test Plan: go test
author
Keegan Carruthers-Smith
committer
GitHub
date
(Dec 6, 2024, 7:38 AM +0200)
commit
39aae4e5
39aae4e513ac7bd2a25a818c60ba3f711b470465
parent
cb9599a0
cb9599a0684c48d5a3ffcec81a48d5358fd1a547
+99
-84
+26
-27
cmd/zoekt-sourcegraph-indexserver/cleanup.go
+26
-27
cmd/zoekt-sourcegraph-indexserver/cleanup.go
···
2
2
3
3
import (
4
4
"fmt"
5
-
"log"
6
5
"os"
7
6
"os/exec"
8
7
"path/filepath"
···
31
30
start := time.Now()
32
31
trashDir := filepath.Join(indexDir, ".trash")
33
32
if err := os.MkdirAll(trashDir, 0o755); err != nil {
34
-
log.Printf("failed to create trash dir: %v", err)
33
+
errorLog.Printf("failed to create trash dir: %v", err)
35
34
}
36
35
37
36
trash := getShards(trashDir)
···
46
45
if shard.ModTime.Before(minAge) {
47
46
old = true
48
47
} else if shard.ModTime.After(now) {
49
-
debug.Printf("trashed shard %s has timestamp in the future, reseting to now", shard.Path)
48
+
debugLog.Printf("trashed shard %s has timestamp in the future, reseting to now", shard.Path)
50
49
_ = os.Chtimes(shard.Path, now, now)
51
50
}
52
51
}
···
55
54
continue
56
55
}
57
56
58
-
log.Printf("removing old shards from trash for %v", repo)
57
+
infoLog.Printf("removing old shards from trash for %v", repo)
59
58
removeAll(shards...)
60
59
delete(trash, repo)
61
60
}
···
89
88
for _, shard := range shards {
90
89
paths = append(paths, filepath.Base(shard.Path))
91
90
}
92
-
log.Printf("removing shards for %v due to multiple repository names: %s", repo, strings.Join(paths, " "))
91
+
infoLog.Printf("removing shards for %v due to multiple repository names: %s", repo, strings.Join(paths, " "))
93
92
94
93
// We may be in both normal and compound shards in this case. First
95
94
// tombstone the compound shards so we don't just rm them.
···
117
116
delete(index, repo)
118
117
119
118
if shards, ok := trash[repo]; ok {
120
-
log.Printf("restoring shards from trash for %v", repo)
119
+
infoLog.Printf("restoring shards from trash for %v", repo)
121
120
moveAll(indexDir, shards)
122
121
continue
123
122
}
124
123
125
124
if s, ok := tombtones[repo]; ok {
126
-
log.Printf("removing tombstone for %v", repo)
125
+
infoLog.Printf("removing tombstone for %v", repo)
127
126
err := zoekt.UnsetTombstone(s.Path, repo)
128
127
if err != nil {
129
-
log.Printf("error removing tombstone for %v: %s", repo, err)
128
+
errorLog.Printf("error removing tombstone for %v: %s", repo, err)
130
129
}
131
130
}
132
131
}
···
150
149
// the files now since cleanup runs with a global lock (no indexing jobs
151
150
// running at the same time).
152
151
if failures, err := filepath.Glob(filepath.Join(indexDir, "*.tmp")); err != nil {
153
-
log.Printf("Glob: %v", err)
152
+
errorLog.Printf("Glob: %v", err)
154
153
} else {
155
154
for _, f := range failures {
156
155
st, err := os.Stat(f)
157
156
if err != nil {
158
-
log.Printf("Stat(%q): %v", f, err)
157
+
errorLog.Printf("Stat(%q): %v", f, err)
159
158
continue
160
159
}
161
160
if !st.IsDir() {
162
-
log.Printf("removing tmp file: %s", f)
161
+
infoLog.Printf("removing tmp file: %s", f)
163
162
os.Remove(f)
164
163
}
165
164
}
···
179
178
func getShards(dir string) map[uint32][]shard {
180
179
d, err := os.Open(dir)
181
180
if err != nil {
182
-
debug.Printf("failed to getShards: %s", dir)
181
+
debugLog.Printf("failed to getShards: %s", dir)
183
182
return nil
184
183
}
185
184
defer d.Close()
···
191
190
path := filepath.Join(dir, n)
192
191
fi, err := os.Stat(path)
193
192
if err != nil {
194
-
debug.Printf("stat failed: %v", err)
193
+
debugLog.Printf("stat failed: %v", err)
195
194
continue
196
195
}
197
196
if fi.IsDir() || filepath.Ext(path) != ".zoekt" {
···
200
199
201
200
repos, _, err := zoekt.ReadMetadataPathAlive(path)
202
201
if err != nil {
203
-
debug.Printf("failed to read shard: %v", err)
202
+
debugLog.Printf("failed to read shard: %v", err)
204
203
continue
205
204
}
206
205
···
260
259
func removeIncompleteShards(dir string) {
261
260
d, err := os.Open(dir)
262
261
if err != nil {
263
-
debug.Printf("failed to removeIncompleteShards: %s", dir)
262
+
debugLog.Printf("failed to removeIncompleteShards: %s", dir)
264
263
return
265
264
}
266
265
defer d.Close()
···
270
269
if incompleteRE.MatchString(n) {
271
270
path := filepath.Join(dir, n)
272
271
if err := os.Remove(path); err != nil {
273
-
debug.Printf("failed to remove incomplete shard %s: %v", path, err)
272
+
debugLog.Printf("failed to remove incomplete shard %s: %v", path, err)
274
273
} else {
275
-
debug.Printf("cleaned up incomplete shard %s", path)
274
+
debugLog.Printf("cleaned up incomplete shard %s", path)
276
275
}
277
276
}
278
277
}
···
288
287
for _, shard := range shards {
289
288
paths, err := zoekt.IndexFilePaths(shard.Path)
290
289
if err != nil {
291
-
debug.Printf("failed to remove shard %s: %v", shard.Path, err)
290
+
debugLog.Printf("failed to remove shard %s: %v", shard.Path, err)
292
291
}
293
292
for _, p := range paths {
294
293
if err := os.Remove(p); err != nil {
295
-
debug.Printf("failed to remove shard file %s: %v", p, err)
294
+
debugLog.Printf("failed to remove shard file %s: %v", p, err)
296
295
}
297
296
}
298
297
}
···
302
301
for i, shard := range shards {
303
302
paths, err := zoekt.IndexFilePaths(shard.Path)
304
303
if err != nil {
305
-
log.Printf("failed to stat shard paths, deleting all shards for %s: %v", shard.RepoName, err)
304
+
errorLog.Printf("failed to stat shard paths, deleting all shards for %s: %v", shard.RepoName, err)
306
305
removeAll(shards...)
307
306
return
308
307
}
···
316
315
// HACK we do not yet support tombstones in compound shard. So we avoid
317
316
// needing to deal with it by always deleting the whole compound shard.
318
317
if strings.HasPrefix(filepath.Base(shard.Path), "compound-") {
319
-
log.Printf("HACK removing compound shard since we don't support tombstoning: %s", shard.Path)
318
+
infoLog.Printf("HACK removing compound shard since we don't support tombstoning: %s", shard.Path)
320
319
removeAll(shard)
321
320
continue
322
321
}
···
331
330
}
332
331
333
332
if err != nil {
334
-
log.Printf("failed to move shard, deleting all shards for %s: %v", shard.RepoName, err)
333
+
errorLog.Printf("failed to move shard, deleting all shards for %s: %v", shard.RepoName, err)
335
334
removeAll(dstShard) // some files may have moved to dst
336
335
removeAll(shards...)
337
336
return
···
369
368
}
370
369
371
370
if err := zoekt.SetTombstone(shards[0].Path, repoID); err != nil {
372
-
log.Printf("error setting tombstone for %d in shard %s: %s. Removing shard\n", repoID, shards[0].Path, err)
371
+
errorLog.Printf("error setting tombstone for %d in shard %s: %s. Removing shard\n", repoID, shards[0].Path, err)
373
372
_ = os.Remove(shards[0].Path)
374
373
}
375
374
return true
···
409
408
path := filepath.Join(s.IndexDir, fn)
410
409
info, err := os.Stat(path)
411
410
if err != nil {
412
-
log.Printf("vacuum stat failed: %v", err)
411
+
errorLog.Printf("vacuum stat failed: %v", err)
413
412
continue
414
413
}
415
414
···
422
421
})
423
422
424
423
if err != nil {
425
-
log.Printf("failed to explode compound shard: shard=%s out=%s err=%s", path, string(b), err)
424
+
errorLog.Printf("failed to explode compound shard: shard=%s out=%s err=%s", path, string(b), err)
426
425
}
427
-
log.Printf("exploded compound shard: shard=%s", path)
426
+
infoLog.Printf("exploded compound shard: shard=%s", path)
428
427
continue
429
428
}
430
429
···
433
432
})
434
433
435
434
if err != nil {
436
-
log.Printf("error while removing tombstones in %s: %s", path, err)
435
+
errorLog.Printf("error while removing tombstones in %s: %s", path, err)
437
436
}
438
437
}
439
438
}
+1
-2
cmd/zoekt-sourcegraph-indexserver/debug.go
+1
-2
cmd/zoekt-sourcegraph-indexserver/debug.go
+1
-2
cmd/zoekt-sourcegraph-indexserver/index.go
+1
-2
cmd/zoekt-sourcegraph-indexserver/index.go
···
7
7
"errors"
8
8
"fmt"
9
9
"io"
10
-
"log"
11
10
"net/url"
12
11
"os"
13
12
"os/exec"
···
321
320
name := o.BuildOptions().RepositoryDescription.Name
322
321
id := o.BuildOptions().RepositoryDescription.ID
323
322
324
-
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)
323
+
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)
325
324
err = fetchOnlyLatestCommits()
326
325
if err != nil {
327
326
return err
+35
-31
cmd/zoekt-sourcegraph-indexserver/main.go
+35
-31
cmd/zoekt-sourcegraph-indexserver/main.go
···
215
215
timeout time.Duration
216
216
}
217
217
218
-
var debug = log.New(io.Discard, "", log.LstdFlags)
218
+
var (
219
+
debugLog = log.New(io.Discard, "[DEBUG] ", log.LstdFlags)
220
+
infoLog = log.New(os.Stderr, "[INFO] ", log.LstdFlags)
221
+
errorLog = log.New(os.Stderr, "[ERROR] ", log.LstdFlags)
222
+
)
219
223
220
224
// our index commands should output something every 100mb they process.
221
225
//
···
263
267
// Periodically check if we have had output. If not kill the process.
264
268
if out.Len() != lastLen {
265
269
lastLen = out.Len()
266
-
log.Printf("still running %s", cmd.Args)
270
+
infoLog.Printf("still running %s", cmd.Args)
267
271
} else {
268
272
// Send quit (C-\) first so we get a stack dump.
269
-
log.Printf("no output for %s, quitting %s", noOutputTimeout, cmd.Args)
273
+
infoLog.Printf("no output for %s, quitting %s", noOutputTimeout, cmd.Args)
270
274
if err := cmd.Process.Signal(unix.SIGQUIT); err != nil {
271
-
log.Println("quit failed:", err)
275
+
errorLog.Println("quit failed:", err)
272
276
}
273
277
274
278
// send sigkill if still running in 10s
···
276
280
}
277
281
278
282
case <-kill:
279
-
log.Printf("still running, killing %s", cmd.Args)
283
+
infoLog.Printf("still running, killing %s", cmd.Args)
280
284
if err := cmd.Process.Kill(); err != nil {
281
-
log.Println("kill failed:", err)
285
+
errorLog.Println("kill failed:", err)
282
286
}
283
287
284
288
case err := <-errC:
···
334
338
// "pkill -SIGUSR1 zoekt-sourcegra"
335
339
for range jitterTicker(s.Interval, unix.SIGUSR1) {
336
340
if b, err := os.ReadFile(filepath.Join(s.IndexDir, pauseFileName)); err == nil {
337
-
log.Printf("indexserver manually paused via PAUSE file: %s", string(bytes.TrimSpace(b)))
341
+
infoLog.Printf("indexserver manually paused via PAUSE file: %s", string(bytes.TrimSpace(b)))
338
342
continue
339
343
}
340
344
341
345
repos, err := s.Sourcegraph.List(context.Background(), listIndexed(s.IndexDir))
342
346
if err != nil {
343
-
log.Printf("error listing repos: %s", err)
347
+
errorLog.Printf("error listing repos: %s", err)
344
348
continue
345
349
}
346
350
347
-
debug.Printf("updating index queue with %d repositories", len(repos.IDs))
351
+
debugLog.Printf("updating index queue with %d repositories", len(repos.IDs))
348
352
349
353
// Stop indexing repos we don't need to track anymore
350
354
removed := s.queue.MaybeRemoveMissing(repos.IDs)
351
355
metricNumStoppedTrackingTotal.Add(float64(len(removed)))
352
356
if len(removed) > 0 {
353
-
log.Printf("stopped tracking %d repositories: %s", len(removed), formatListUint32(removed, 5))
357
+
infoLog.Printf("stopped tracking %d repositories: %s", len(removed), formatListUint32(removed, 5))
354
358
}
355
359
356
360
cleanupDone := make(chan struct{})
···
450
454
metricIndexingDelay.WithLabelValues(string(state), repoNameForMetric(opts.Name)).Observe(indexDelay.Seconds())
451
455
452
456
if err != nil {
453
-
log.Printf("error indexing %s: %s", args.String(), err)
457
+
errorLog.Printf("error indexing %s: %s", args.String(), err)
454
458
}
455
459
456
460
switch state {
···
468
472
sglog.Duration("index_delay", indexDelay),
469
473
)
470
474
case indexStateSuccessMeta:
471
-
log.Printf("updated meta %s in %v", args.String(), elapsed)
475
+
infoLog.Printf("updated meta %s in %v", args.String(), elapsed)
472
476
}
473
477
s.queue.SetIndexed(opts, state)
474
478
})
···
477
481
// Someone else is processing the repository. We can just skip this job
478
482
// since the repository will be added back to the queue and we will
479
483
// converge to the correct behaviour.
480
-
debug.Printf("index job for repository already running: %s", args)
484
+
debugLog.Printf("index job for repository already running: %s", args)
481
485
continue
482
486
}
483
487
}
···
593
597
594
598
switch incrementalState {
595
599
case build.IndexStateEqual:
596
-
debug.Printf("%s index already up to date. Shard=%s", args.String(), fn)
600
+
debugLog.Printf("%s index already up to date. Shard=%s", args.String(), fn)
597
601
return indexStateNoop, nil
598
602
599
603
case build.IndexStateMeta:
600
-
log.Printf("updating index.meta %s", args.String())
604
+
infoLog.Printf("updating index.meta %s", args.String())
601
605
602
606
// TODO(stefan) handle mergeMeta for tenant id.
603
607
if err := mergeMeta(bo); err != nil {
604
-
log.Printf("falling back to full update: failed to update index.meta %s: %s", args.String(), err)
608
+
errorLog.Printf("falling back to full update: failed to update index.meta %s: %s", args.String(), err)
605
609
} else {
606
610
return indexStateSuccessMeta, nil
607
611
}
608
612
609
613
case build.IndexStateCorrupt:
610
-
log.Printf("falling back to full update: corrupt index: %s", args.String())
614
+
infoLog.Printf("falling back to full update: corrupt index: %s", args.String())
611
615
}
612
616
}
613
617
614
-
log.Printf("updating index %s reason=%s", args.String(), reason)
618
+
infoLog.Printf("updating index %s reason=%s", args.String(), reason)
615
619
616
620
metricIndexingTotal.Inc()
617
621
c := gitIndexConfig{
···
906
910
}
907
911
_, err = fmt.Fprintf(tw, "%d\t%s\n", id, name)
908
912
if err != nil {
909
-
debug.Printf("handleDebugList: %s\n", err.Error())
913
+
debugLog.Printf("handleDebugList: %s\n", err.Error())
910
914
}
911
915
}
912
916
s.queue.mu.Unlock()
···
969
973
}
970
974
_, err = fmt.Fprintf(tw, "%d\t%s\n", id, name)
971
975
if err != nil {
972
-
debug.Printf("handleDebugIndexed: %s\n", err.Error())
976
+
debugLog.Printf("handleDebugIndexed: %s\n", err.Error())
973
977
}
974
978
}
975
979
s.queue.mu.Unlock()
···
1207
1211
func setCompoundShardCounter(indexDir string) {
1208
1212
fns, err := filepath.Glob(filepath.Join(indexDir, "compound-*.zoekt"))
1209
1213
if err != nil {
1210
-
log.Printf("setCompoundShardCounter: %s\n", err)
1214
+
errorLog.Printf("setCompoundShardCounter: %s\n", err)
1211
1215
return
1212
1216
}
1213
1217
metricNumberCompoundShards.Set(float64(len(fns)))
···
1298
1302
s.addDebugHandlers(mux)
1299
1303
1300
1304
go func() {
1301
-
debug.Printf("serving HTTP on %s", conf.listen)
1305
+
debugLog.Printf("serving HTTP on %s", conf.listen)
1302
1306
log.Fatal(http.ListenAndServe(conf.listen, mux))
1303
1307
}()
1304
1308
···
1330
1334
if err := os.Chmod(socket, 0o777); err != nil {
1331
1335
return fmt.Errorf("failed to change permission of socket %s: %w", socket, err)
1332
1336
}
1333
-
debug.Printf("serving HTTP on %s", socket)
1337
+
debugLog.Printf("serving HTTP on %s", socket)
1334
1338
return http.Serve(l, mux)
1335
1339
}
1336
-
debug.Print(serveHTTPOverSocket())
1340
+
debugLog.Print(serveHTTPOverSocket())
1337
1341
}()
1338
1342
}
1339
1343
···
1392
1396
}
1393
1397
1394
1398
if srcLogLevelIsDebug() {
1395
-
debug = log.New(os.Stderr, "", log.LstdFlags)
1399
+
debugLog.SetOutput(os.Stderr)
1396
1400
}
1397
1401
1398
1402
reposWithSeparateIndexingMetrics = getEnvWithDefaultEmptySet("INDEXING_METRICS_REPOS_ALLOWLIST")
1399
1403
if len(reposWithSeparateIndexingMetrics) > 0 {
1400
-
debug.Printf("capturing separate indexing metrics for: %s", joinStringSet(reposWithSeparateIndexingMetrics, ", "))
1404
+
debugLog.Printf("capturing separate indexing metrics for: %s", joinStringSet(reposWithSeparateIndexingMetrics, ", "))
1401
1405
}
1402
1406
1403
1407
deltaBuildRepositoriesAllowList := getEnvWithDefaultEmptySet("DELTA_BUILD_REPOS_ALLOWLIST")
1404
1408
if len(deltaBuildRepositoriesAllowList) > 0 {
1405
-
debug.Printf("using delta shard builds for: %s", joinStringSet(deltaBuildRepositoriesAllowList, ", "))
1409
+
debugLog.Printf("using delta shard builds for: %s", joinStringSet(deltaBuildRepositoriesAllowList, ", "))
1406
1410
}
1407
1411
1408
1412
deltaShardNumberFallbackThreshold := getEnvWithDefaultUint64("DELTA_SHARD_NUMBER_FALLBACK_THRESHOLD", 150)
1409
1413
if deltaShardNumberFallbackThreshold > 0 {
1410
-
debug.Printf("setting delta shard fallback threshold to %d shard(s)", deltaShardNumberFallbackThreshold)
1414
+
debugLog.Printf("setting delta shard fallback threshold to %d shard(s)", deltaShardNumberFallbackThreshold)
1411
1415
} else {
1412
-
debug.Printf("disabling delta build fallback behavior - delta builds will be performed regardless of the number of preexisting shards")
1416
+
debugLog.Printf("disabling delta build fallback behavior - delta builds will be performed regardless of the number of preexisting shards")
1413
1417
}
1414
1418
1415
1419
reposShouldSkipSymbolsCalculation := getEnvWithDefaultEmptySet("SKIP_SYMBOLS_REPOS_ALLOWLIST")
1416
1420
if len(reposShouldSkipSymbolsCalculation) > 0 {
1417
-
debug.Printf("skipping generating symbols metadata for: %s", joinStringSet(reposShouldSkipSymbolsCalculation, ", "))
1421
+
debugLog.Printf("skipping generating symbols metadata for: %s", joinStringSet(reposShouldSkipSymbolsCalculation, ", "))
1418
1422
}
1419
1423
1420
1424
indexingTimeout := getEnvWithDefaultDuration("INDEXING_TIMEOUT", defaultIndexingTimeout)
1421
1425
if indexingTimeout != defaultIndexingTimeout {
1422
-
debug.Printf("using configured indexing timeout: %s", indexingTimeout)
1426
+
debugLog.Printf("using configured indexing timeout: %s", indexingTimeout)
1423
1427
}
1424
1428
1425
1429
var sg Sourcegraph
+3
cmd/zoekt-sourcegraph-indexserver/main_test.go
+3
cmd/zoekt-sourcegraph-indexserver/main_test.go
+9
-10
cmd/zoekt-sourcegraph-indexserver/merge.go
+9
-10
cmd/zoekt-sourcegraph-indexserver/merge.go
···
2
2
3
3
import (
4
4
"bytes"
5
-
"log"
6
5
"os"
7
6
"os/exec"
8
7
"path/filepath"
···
59
58
// Guard against the user triggering competing merge jobs with the debug
60
59
// command.
61
60
if !mergeRunning.CompareAndSwap(false, true) {
62
-
log.Printf("merge already running")
61
+
infoLog.Printf("merge already running")
63
62
return
64
63
}
65
64
defer mergeRunning.Store(false)
···
74
73
next = false
75
74
s.muIndexDir.Global(func() {
76
75
candidates, excluded := loadCandidates(s.IndexDir, s.mergeOpts)
77
-
log.Printf("loadCandidates: candidates=%d excluded=%d", len(candidates), excluded)
76
+
infoLog.Printf("loadCandidates: candidates=%d excluded=%d", len(candidates), excluded)
78
77
79
78
c := pickCandidates(candidates, s.mergeOpts.targetSizeBytes)
80
79
if len(c.shards) <= 1 {
81
-
log.Printf("could not find enough shards to build a compound shard")
80
+
infoLog.Printf("could not find enough shards to build a compound shard")
82
81
return
83
82
}
84
-
log.Printf("start merging: shards=%d total_size=%.2fMiB", len(c.shards), float64(c.size)/(1024*1024))
83
+
infoLog.Printf("start merging: shards=%d total_size=%.2fMiB", len(c.shards), float64(c.size)/(1024*1024))
85
84
86
85
var paths []string
87
86
for _, p := range c.shards {
···
103
102
durationSeconds := time.Since(start).Seconds()
104
103
metricShardMergingDuration.WithLabelValues(strconv.FormatBool(err != nil)).Observe(durationSeconds)
105
104
if err != nil {
106
-
log.Printf("error merging shards: stdout=%s, stderr=%s, durationSeconds=%.2f err=%s", stdoutBuf.String(), stderrBuf.String(), durationSeconds, err)
105
+
errorLog.Printf("error merging shards: stdout=%s, stderr=%s, durationSeconds=%.2f err=%s", stdoutBuf.String(), stderrBuf.String(), durationSeconds, err)
107
106
return
108
107
}
109
108
110
-
log.Printf("finished merging: shard=%s durationSeconds=%.2f", stdoutBuf.String(), durationSeconds)
109
+
infoLog.Printf("finished merging: shard=%s durationSeconds=%.2f", stdoutBuf.String(), durationSeconds)
111
110
112
111
next = true
113
112
})
···
127
126
128
127
d, err := os.Open(dir)
129
128
if err != nil {
130
-
debug.Printf("failed to load candidates: %s", dir)
129
+
debugLog.Printf("failed to load candidates: %s", dir)
131
130
return []candidate{}, excluded
132
131
}
133
132
defer d.Close()
···
139
138
140
139
fi, err := os.Stat(path)
141
140
if err != nil {
142
-
debug.Printf("stat failed for %s: %s", n, err)
141
+
debugLog.Printf("stat failed for %s: %s", n, err)
143
142
continue
144
143
}
145
144
···
206
205
207
206
repos, _, err := zoekt.ReadMetadataPath(path)
208
207
if err != nil {
209
-
debug.Printf("failed to load metadata for %s\n", fi.Name())
208
+
debugLog.Printf("failed to load metadata for %s\n", fi.Name())
210
209
return true
211
210
}
212
211
+1
-1
cmd/zoekt-sourcegraph-indexserver/owner.go
+1
-1
cmd/zoekt-sourcegraph-indexserver/owner.go
···
53
53
if err := o.Check(); errors.Is(err, fs.ErrNotExist) {
54
54
// do nothing, first run so we just write out the file
55
55
} else if errors.As(err, &ownerErr) {
56
-
debug.Printf("WARN: detected a change in ownership at startup. You can ignore this if you only have one zoekt replica: %s", err)
56
+
debugLog.Printf("WARN: detected a change in ownership at startup. You can ignore this if you only have one zoekt replica: %s", err)
57
57
} else if err != nil {
58
58
return err
59
59
}
+1
-1
cmd/zoekt-sourcegraph-indexserver/queue.go
+1
-1
cmd/zoekt-sourcegraph-indexserver/queue.go
+6
-6
shards/shards.go
+6
-6
shards/shards.go
···
303
303
tl.ss.replace(chunk)
304
304
}
305
305
306
-
log.Printf("loading %d shard(s): %s", len(keys), humanTruncateList(keys, 5))
306
+
log.Printf("[INFO] loading %d shard(s): %s", len(keys), humanTruncateList(keys, 5))
307
307
308
308
lastProgress := time.Now()
309
309
for i, key := range keys {
310
310
// If taking a while to start-up occasionally give a progress message
311
311
if time.Since(lastProgress) > 5*time.Second {
312
-
log.Printf("still need to load %d shards...", len(keys)-i)
312
+
log.Printf("[INFO] still need to load %d shards...", len(keys)-i)
313
313
lastProgress = time.Now()
314
314
315
315
publishLoaded()
···
325
325
shard, err := loadShard(key)
326
326
if err != nil {
327
327
metricShardsLoadFailedTotal.Inc()
328
-
log.Printf("reloading: %s, err %v ", key, err)
328
+
log.Printf("[ERROR] reloading: %s, err %v ", key, err)
329
329
return
330
330
}
331
331
metricShardsLoadedTotal.Inc()
···
896
896
defer func() {
897
897
metricSearchShardRunning.Dec()
898
898
if e := recover(); e != nil {
899
-
log.Printf("crashed shard: %s: %#v, %s", s, e, debug.Stack())
899
+
log.Printf("[ERROR] crashed shard: %s: %#v, %s", s, e, debug.Stack())
900
900
901
901
if sr == nil {
902
902
sr = &zoekt.SearchResult{}
···
918
918
defer func() {
919
919
metricListShardRunning.Dec()
920
920
if r := recover(); r != nil {
921
-
log.Printf("crashed shard: %s: %s, %s", s.String(), r, debug.Stack())
921
+
log.Printf("[ERROR] crashed shard: %s: %s, %s", s.String(), r, debug.Stack())
922
922
sink <- shardListResult{
923
923
&zoekt.RepoList{Crashes: 1}, nil,
924
924
}
···
1088
1088
// rankedShard.repos being set.
1089
1089
result, err := s.List(systemtenant.UnsafeCtx, &q, nil)
1090
1090
if err != nil {
1091
-
log.Printf("mkRankedShard(%s): failed to cache repository list: %v", s, err)
1091
+
log.Printf("[ERROR] mkRankedShard(%s): failed to cache repository list: %v", s, err)
1092
1092
return &rankedShard{Searcher: s}
1093
1093
}
1094
1094
+13
-1
shards/shards_test.go
+13
-1
shards/shards_test.go
···
17
17
import (
18
18
"bytes"
19
19
"context"
20
+
"flag"
20
21
"fmt"
21
22
"hash/fnv"
23
+
"io"
22
24
"log"
23
25
"math"
24
26
"os"
···
39
41
"github.com/sourcegraph/zoekt/query"
40
42
)
41
43
44
+
func TestMain(m *testing.M) {
45
+
flag.Parse()
46
+
if !testing.Verbose() {
47
+
log.SetOutput(io.Discard)
48
+
}
49
+
os.Exit(m.Run())
50
+
}
51
+
42
52
type crashSearcher struct{}
43
53
44
54
func (s *crashSearcher) Search(ctx context.Context, q query.Q, opts *zoekt.SearchOptions) (*zoekt.SearchResult, error) {
···
59
69
60
70
func TestCrashResilience(t *testing.T) {
61
71
out := &bytes.Buffer{}
72
+
oldOut := log.Writer()
62
73
log.SetOutput(out)
63
-
defer log.SetOutput(os.Stderr)
74
+
defer log.SetOutput(oldOut)
75
+
64
76
ss := newShardedSearcher(2)
65
77
ss.ranked.Store([]*rankedShard{{Searcher: &crashSearcher{}}})
66
78
+3
-3
shards/watcher.go
+3
-3
shards/watcher.go
···
179
179
}
180
180
181
181
if len(toDrop) > 0 {
182
-
log.Printf("unloading %d shard(s): %s", len(toDrop), humanTruncateList(toDrop, 5))
182
+
log.Printf("[INFO] unloading %d shard(s): %s", len(toDrop), humanTruncateList(toDrop, 5))
183
183
}
184
184
185
185
s.loader.drop(toDrop...)
···
244
244
// Ignore ErrEventOverflow since we rely on the presence of events so
245
245
// safe to ignore.
246
246
if err != nil && err != fsnotify.ErrEventOverflow {
247
-
log.Println("watcher error:", err)
247
+
log.Println("[ERROR] watcher error:", err)
248
248
}
249
249
250
250
case <-s.quit:
···
260
260
defer close(s.stopped)
261
261
for range signal {
262
262
if err := s.scan(); err != nil {
263
-
log.Println("watcher error:", err)
263
+
log.Println("[ERROR] watcher error:", err)
264
264
}
265
265
}
266
266
}()