boltless.me / zoekt
fork of https://github.com/sourcegraph/zoekt
0
Fork 0

Configure Feed

Select the types of activity you want to include in your feed.

webserver: slow query logging with traceID (#120)

* webserver: http logging with traceid

This changeset adds HTTP request logging with a traceid which should
help us jump from logs to traces when using Grafana Cloud, and find
trace ids of past requests that were slow.

* fixup! remove dangling import

* loggedSearcher: Log traceID of slow searches

* fixup! Remove HTTPTraceMiddleware

* fixup! Always log

author
Tomás Senart committer
GitHub date (Aug 5, 2021, 4:31 PM +0200) commit e200b125 parent 68b5aae7
+108 -19
+83 -14
cmd/zoekt-webserver/main.go
··· 246 246 log.Println("watchdog disabled") 247 247 } 248 248 249 - srv := &http.Server{Addr: *listen, Handler: handler} 249 + srv := &http.Server{ 250 + Addr: *listen, 251 + Handler: handler, 252 + } 250 253 251 254 go func() { 252 255 if debug { ··· 402 405 zoekt.Streamer 403 406 } 404 407 405 - func (s *loggedSearcher) Search(ctx context.Context, q query.Q, opts *zoekt.SearchOptions) (*zoekt.SearchResult, error) { 406 - sr, err := s.Streamer.Search(ctx, q, opts) 407 - if err != nil { 408 - log.Printf("EROR: search failed q=%s: %s", q.String(), err.Error()) 409 - } 410 - if sr != nil { 411 - log.Printf("DBUG: search q=%s Options{EstimateDocCount=%v Whole=%v ShardMaxMatchCount=%v TotalMaxMatchCount=%v ShardMaxImportantMatch=%v TotalMaxImportantMatch=%v MaxWallTime=%v MaxDocDisplayCount=%v} Stats{ContentBytesLoaded=%v IndexBytesLoaded=%v Crashes=%v Duration=%v FileCount=%v ShardFilesConsidered=%v FilesConsidered=%v FilesLoaded=%v FilesSkipped=%v ShardsSkipped=%v MatchCount=%v NgramMatches=%v Wait=%v}", q.String(), opts.EstimateDocCount, opts.Whole, opts.ShardMaxMatchCount, opts.TotalMaxMatchCount, opts.ShardMaxImportantMatch, opts.TotalMaxImportantMatch, opts.MaxWallTime, opts.MaxDocDisplayCount, sr.Stats.ContentBytesLoaded, sr.Stats.IndexBytesLoaded, sr.Stats.Crashes, sr.Stats.Duration, sr.Stats.FileCount, sr.Stats.ShardFilesConsidered, sr.Stats.FilesConsidered, sr.Stats.FilesLoaded, sr.Stats.FilesSkipped, sr.Stats.ShardsSkipped, sr.Stats.MatchCount, sr.Stats.NgramMatches, sr.Stats.Wait) 412 - } 413 - return sr, err 408 + func (s *loggedSearcher) Search( 409 + ctx context.Context, 410 + q query.Q, 411 + opts *zoekt.SearchOptions, 412 + ) (sr *zoekt.SearchResult, err error) { 413 + defer func() { 414 + var stats *zoekt.Stats 415 + if sr != nil { 416 + stats = &sr.Stats 417 + } 418 + s.log(ctx, q, opts, stats, err) 419 + }() 420 + 421 + return s.Streamer.Search(ctx, q, opts) 414 422 } 415 423 416 - func (s *loggedSearcher) StreamSearch(ctx context.Context, q query.Q, opts *zoekt.SearchOptions, sender zoekt.Sender) error { 424 + func (s *loggedSearcher) StreamSearch( 425 + ctx context.Context, 426 + q query.Q, 427 + opts *zoekt.SearchOptions, 428 + sender zoekt.Sender, 429 + ) error { 417 430 var ( 418 431 mu sync.Mutex 419 432 stats zoekt.Stats ··· 424 437 mu.Unlock() 425 438 sender.Send(event) 426 439 })) 440 + 441 + s.log(ctx, q, opts, &stats, err) 442 + 443 + return err 444 + } 445 + 446 + func (s *loggedSearcher) log(ctx context.Context, q query.Q, opts *zoekt.SearchOptions, st *zoekt.Stats, err error) { 447 + id := traceID(ctx) 427 448 if err != nil { 428 - log.Printf("EROR: search failed q=%s: %s", q.String(), err.Error()) 449 + log.Printf("EROR: search failed traceID=%s q=%s: %s", id, q.String(), err.Error()) 450 + return 429 451 } 430 - log.Printf("DBUG: search q=%s Options{EstimateDocCount=%v Whole=%v ShardMaxMatchCount=%v TotalMaxMatchCount=%v ShardMaxImportantMatch=%v TotalMaxImportantMatch=%v MaxWallTime=%v MaxDocDisplayCount=%v} Stats{ContentBytesLoaded=%v IndexBytesLoaded=%v Crashes=%v Duration=%v FileCount=%v ShardFilesConsidered=%v FilesConsidered=%v FilesLoaded=%v FilesSkipped=%v ShardsSkipped=%v MatchCount=%v NgramMatches=%v Wait=%v}", q.String(), opts.EstimateDocCount, opts.Whole, opts.ShardMaxMatchCount, opts.TotalMaxMatchCount, opts.ShardMaxImportantMatch, opts.TotalMaxImportantMatch, opts.MaxWallTime, opts.MaxDocDisplayCount, stats.ContentBytesLoaded, stats.IndexBytesLoaded, stats.Crashes, stats.Duration, stats.FileCount, stats.ShardFilesConsidered, stats.FilesConsidered, stats.FilesLoaded, stats.FilesSkipped, stats.ShardsSkipped, stats.MatchCount, stats.NgramMatches, stats.Wait) 431 - return err 452 + 453 + if st == nil { 454 + return 455 + } 456 + 457 + log.Printf( 458 + "DBUG: search traceID=%s q=%s Options{EstimateDocCount=%v Whole=%v ShardMaxMatchCount=%v TotalMaxMatchCount=%v ShardMaxImportantMatch=%v TotalMaxImportantMatch=%v MaxWallTime=%v MaxDocDisplayCount=%v} Stats{ContentBytesLoaded=%v IndexBytesLoaded=%v Crashes=%v Duration=%v FileCount=%v ShardFilesConsidered=%v FilesConsidered=%v FilesLoaded=%v FilesSkipped=%v ShardsSkipped=%v MatchCount=%v NgramMatches=%v Wait=%v}", 459 + id, 460 + q.String(), 461 + opts.EstimateDocCount, 462 + opts.Whole, 463 + opts.ShardMaxMatchCount, 464 + opts.TotalMaxMatchCount, 465 + opts.ShardMaxImportantMatch, 466 + opts.TotalMaxImportantMatch, 467 + opts.MaxWallTime, 468 + opts.MaxDocDisplayCount, 469 + st.ContentBytesLoaded, 470 + st.IndexBytesLoaded, 471 + st.Crashes, 472 + st.Duration, 473 + st.FileCount, 474 + st.ShardFilesConsidered, 475 + st.FilesConsidered, 476 + st.FilesLoaded, 477 + st.FilesSkipped, 478 + st.ShardsSkipped, 479 + st.MatchCount, 480 + st.NgramMatches, 481 + st.Wait, 482 + ) 483 + } 484 + 485 + // traceID returns a trace ID, if any, found in the given context. 486 + func traceID(ctx context.Context) string { 487 + span := opentracing.SpanFromContext(ctx) 488 + if span == nil { 489 + return "" 490 + } 491 + return traceIDFromSpan(span) 492 + } 493 + 494 + // traceIDFromSpan returns a trace ID, if any, found in the given span. 495 + func traceIDFromSpan(span opentracing.Span) string { 496 + spanCtx, ok := span.Context().(jaeger.SpanContext) 497 + if !ok { 498 + return "" 499 + } 500 + return spanCtx.TraceID().String() 432 501 } 433 502 434 503 func initializeJaeger() {
+1
go.mod
··· 21 21 github.com/kevinburke/ssh_config v1.1.0 // indirect 22 22 github.com/kylelemons/godebug v1.1.0 23 23 github.com/mxk/go-flowrate v0.0.0-20140419014527-cca7078d478f 24 + github.com/opentracing-contrib/go-stdlib v1.0.0 // indirect 24 25 github.com/opentracing/opentracing-go v1.2.0 25 26 github.com/prometheus/client_golang v1.5.1 26 27 github.com/prometheus/procfs v0.0.10 // indirect
+3
go.sum
··· 369 369 github.com/onsi/gomega v1.7.1/go.mod h1:XdKZgCCFLUoM/7CFJVPcG8C1xQ1AJ0vpAezJrB7JYyY= 370 370 github.com/onsi/gomega v1.8.1/go.mod h1:Ho0h+IUsWyvy1OpqCwxlQ/21gkhVunqlU8fDGcoTdcA= 371 371 github.com/onsi/gomega v1.9.0/go.mod h1:Ho0h+IUsWyvy1OpqCwxlQ/21gkhVunqlU8fDGcoTdcA= 372 + github.com/opentracing-contrib/go-stdlib v1.0.0 h1:TBS7YuVotp8myLon4Pv7BtCBzOTo1DeZCld0Z63mW2w= 373 + github.com/opentracing-contrib/go-stdlib v1.0.0/go.mod h1:qtI1ogk+2JhVPIXVc6q+NHziSmy2W5GbdQZFUHADCBU= 374 + github.com/opentracing/opentracing-go v1.1.0/go.mod h1:UkNAQd3GIcIGf0SeVgPpRdFStlNbqXla1AfSYxPUl2o= 372 375 github.com/opentracing/opentracing-go v1.2.0 h1:uEJPy/1a5RIPAJ0Ov+OIO8OxWu77jEv+1B0VhjKrZUs= 373 376 github.com/opentracing/opentracing-go v1.2.0/go.mod h1:GxEUsuufX4nBwe+T+Wl9TAgYrxe9dPLANfrWvHYVTgc= 374 377 github.com/pborman/uuid v1.2.0/go.mod h1:X/NO0urCmaxf9VXbdlT7C2Yzkj2IKimNn4k+gtPdI/k=
+1 -1
stream/stream.go
··· 75 75 76 76 // mu protects aggStats and concurrent writes to the stream. 77 77 mu := sync.Mutex{} 78 - var aggStats = zoekt.Stats{} 78 + aggStats := zoekt.Stats{} 79 79 send := func(zsr *zoekt.SearchResult) { 80 80 err := eventWriter.event(eventMatches, zsr) 81 81 if err != nil {
+20 -4
web/trace.go
··· 17 17 Searcher zoekt.Streamer 18 18 } 19 19 20 - func (s traceAwareSearcher) Search(ctx context.Context, q query.Q, opts *zoekt.SearchOptions) (*zoekt.SearchResult, error) { 20 + func (s traceAwareSearcher) Search( 21 + ctx context.Context, 22 + q query.Q, 23 + opts *zoekt.SearchOptions, 24 + ) (*zoekt.SearchResult, error) { 21 25 ctx, finish := getTraceContext(ctx, "zoekt.traceAwareSearcher.Search", opts.Trace, opts.SpanContext) 22 26 defer finish() 23 27 return s.Searcher.Search(ctx, q, opts) 24 28 } 25 29 26 - func (s traceAwareSearcher) StreamSearch(ctx context.Context, q query.Q, opts *zoekt.SearchOptions, sender zoekt.Sender) error { 30 + func (s traceAwareSearcher) StreamSearch( 31 + ctx context.Context, 32 + q query.Q, 33 + opts *zoekt.SearchOptions, 34 + sender zoekt.Sender, 35 + ) error { 27 36 ctx, finish := getTraceContext(ctx, "zoekt.traceAwareSearcher.StreamSearch", opts.Trace, opts.SpanContext) 28 37 defer finish() 29 38 return s.Searcher.StreamSearch(ctx, q, opts, sender) 30 39 } 31 40 32 - func getTraceContext(ctx context.Context, opName string, traceEnabled bool, spanContext map[string]string) (context.Context, func()) { 41 + func getTraceContext( 42 + ctx context.Context, 43 + opName string, 44 + traceEnabled bool, 45 + spanContext map[string]string, 46 + ) (context.Context, func()) { 33 47 ctx = trace.WithOpenTracingEnabled(ctx, traceEnabled) 34 48 finish := func() {} 35 49 if traceEnabled && spanContext != nil { 36 - spanContext, err := trace.GetOpenTracer(ctx, nil).Extract(opentracing.TextMap, opentracing.TextMapCarrier(spanContext)) 50 + spanContext, err := trace.GetOpenTracer(ctx, nil). 51 + Extract(opentracing.TextMap, opentracing.TextMapCarrier(spanContext)) 37 52 if err != nil { 38 53 log.Printf("Error extracting span from opts: %s", err) 39 54 } ··· 45 60 } 46 61 return ctx, finish 47 62 } 63 + 48 64 func (s traceAwareSearcher) List(ctx context.Context, q query.Q, opts *zoekt.ListOptions) (*zoekt.RepoList, error) { 49 65 return s.Searcher.List(ctx, q, opts) 50 66 }