From ebb12072c31108bf3e1e8fc0070fd8e4abaacd69 Mon Sep 17 00:00:00 2001 From: Jaime Soriano Pastor Date: Mon, 16 Mar 2020 16:17:15 +0100 Subject: [PATCH 1/5] Ensure pprof endpoint is listening on startup pprof HTTP endpoint was being initialized asynchronously. In tests we have found that sometimes after Metricbeat has started, it fails to connect to the pprof endpoint. This can happen if the server is not listening before the rest of the beat is initialized. This change ensures that the listener for this endpoint is started before continuing with the rest of the initialization. Some comments and error messages have been polished. --- libbeat/service/service.go | 30 +++++++++++++++++++----------- 1 file changed, 19 insertions(+), 11 deletions(-) diff --git a/libbeat/service/service.go b/libbeat/service/service.go index 2d88b25f782..c550e0b30f1 100644 --- a/libbeat/service/service.go +++ b/libbeat/service/service.go @@ -23,6 +23,7 @@ import ( "flag" "fmt" "log" + "net" "net/http" _ "net/http/pprof" "os" @@ -97,24 +98,31 @@ func BeforeRun() { if *httpprof != "" { logp.Info("start pprof endpoint") - go func() { - mux := http.NewServeMux() + mux := http.NewServeMux() - // register pprof handler - mux.HandleFunc("/debug/pprof/", func(w http.ResponseWriter, r *http.Request) { - http.DefaultServeMux.ServeHTTP(w, r) - }) + // Register pprof handler + mux.HandleFunc("/debug/pprof/", func(w http.ResponseWriter, r *http.Request) { + http.DefaultServeMux.ServeHTTP(w, r) + }) - // register metrics handler - mux.HandleFunc("/debug/vars", metricsHandler) + // Register metrics handler + mux.HandleFunc("/debug/vars", metricsHandler) - endpoint := http.ListenAndServe(*httpprof, mux) - logp.Info("finished pprof endpoint: %v", endpoint) + // Ensure we are listening before returning + listener, err := net.Listen("tcp", *httpprof) + if err != nil { + log.Fatalf("Failed to start stats listener: %v", err) + } + + go func() { + // Serve returns always a non-nil error + err := http.Serve(listener, mux) + logp.Info("Finished pprof endpoint: %v", err) }() } } -// report expvar and all libbeat/monitoring metrics +// metricsHandler reports expvar and all libbeat/monitoring metrics func metricsHandler(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-Type", "application/json; charset=utf-8") From 7a2f23b09263d96b12d9ef954c324e0521c144b4 Mon Sep 17 00:00:00 2001 From: Jaime Soriano Pastor Date: Mon, 16 Mar 2020 16:36:36 +0100 Subject: [PATCH 2/5] Log fatal errors when starting profilers --- libbeat/service/service.go | 45 ++++++++++++++++++++------------------ 1 file changed, 24 insertions(+), 21 deletions(-) diff --git a/libbeat/service/service.go b/libbeat/service/service.go index c550e0b30f1..a22f00b1fef 100644 --- a/libbeat/service/service.go +++ b/libbeat/service/service.go @@ -22,7 +22,6 @@ import ( "expvar" "flag" "fmt" - "log" "net" "net/http" _ "net/http/pprof" @@ -91,35 +90,39 @@ func BeforeRun() { if withCPUProfile() { cpuOut, err := os.Create(*cpuprofile) if err != nil { - log.Fatal(err) + logp.Err("Failed to create CPU profile: %v", err) + os.Exit(1) } pprof.StartCPUProfile(cpuOut) } - if *httpprof != "" { - logp.Info("start pprof endpoint") - mux := http.NewServeMux() + if *httpprof == "" { + return + } - // Register pprof handler - mux.HandleFunc("/debug/pprof/", func(w http.ResponseWriter, r *http.Request) { - http.DefaultServeMux.ServeHTTP(w, r) - }) + logp.Info("Start pprof endpoint") + mux := http.NewServeMux() - // Register metrics handler - mux.HandleFunc("/debug/vars", metricsHandler) + // Register pprof handler + mux.HandleFunc("/debug/pprof/", func(w http.ResponseWriter, r *http.Request) { + http.DefaultServeMux.ServeHTTP(w, r) + }) - // Ensure we are listening before returning - listener, err := net.Listen("tcp", *httpprof) - if err != nil { - log.Fatalf("Failed to start stats listener: %v", err) - } + // Register metrics handler + mux.HandleFunc("/debug/vars", metricsHandler) - go func() { - // Serve returns always a non-nil error - err := http.Serve(listener, mux) - logp.Info("Finished pprof endpoint: %v", err) - }() + // Ensure we are listening before returning + listener, err := net.Listen("tcp", *httpprof) + if err != nil { + logp.Err("Failed to start stats listener: %v", err) + os.Exit(1) } + + go func() { + // Serve returns always a non-nil error + err := http.Serve(listener, mux) + logp.Info("Finished pprof endpoint: %v", err) + }() } // metricsHandler reports expvar and all libbeat/monitoring metrics From 6dae23169bfc50abdb0517b56aae078b971377a3 Mon Sep 17 00:00:00 2001 From: Jaime Soriano Pastor Date: Mon, 16 Mar 2020 16:40:07 +0100 Subject: [PATCH 3/5] Add changelog entry --- CHANGELOG.next.asciidoc | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.next.asciidoc b/CHANGELOG.next.asciidoc index a2cf0514d0e..b3a0b616cd6 100644 --- a/CHANGELOG.next.asciidoc +++ b/CHANGELOG.next.asciidoc @@ -68,6 +68,7 @@ https://github.com/elastic/beats/compare/v7.0.0-alpha2...master[Check the HEAD d - Fix `NewContainerMetadataEnricher` to use default config for kubernetes module. {pull}16857[16857] - Improve some logging messages for add_kubernetes_metadata processor {pull}16866[16866] - Fix k8s metadata issue regarding node labels not shown up on root level of metadata. {pull}16834[16834] +- Fail to start if httpprof is used and it cannot be initialized. {pull}17028[17028] *Auditbeat* From 3cd26bfb068fc8990b361278c670caa6ee5dfbac Mon Sep 17 00:00:00 2001 From: Jaime Soriano Pastor Date: Mon, 16 Mar 2020 18:17:41 +0100 Subject: [PATCH 4/5] Remove global logger from libbeat service --- libbeat/service/service.go | 31 +++++++++++++++++++------------ 1 file changed, 19 insertions(+), 12 deletions(-) diff --git a/libbeat/service/service.go b/libbeat/service/service.go index a22f00b1fef..84c017b3587 100644 --- a/libbeat/service/service.go +++ b/libbeat/service/service.go @@ -41,6 +41,7 @@ import ( // the service shut downs gracefully. func HandleSignals(stopFunction func(), cancel context.CancelFunc) { var callback sync.Once + var logger = logp.NewLogger("service") // On termination signals, gracefully stop the Beat sigc := make(chan os.Signal, 1) @@ -50,9 +51,9 @@ func HandleSignals(stopFunction func(), cancel context.CancelFunc) { switch sig { case syscall.SIGINT, syscall.SIGTERM: - logp.Debug("service", "Received sigterm/sigint, stopping") + logger.Debug("Received sigterm/sigint, stopping") case syscall.SIGHUP: - logp.Debug("service", "Received sighup, stopping") + logger.Debug("Received sighup, stopping") } cancel() @@ -61,7 +62,7 @@ func HandleSignals(stopFunction func(), cancel context.CancelFunc) { // Handle the Windows service events go ProcessWindowsControlEvents(func() { - logp.Debug("service", "Received svc stop/shutdown request") + logger.Debug("Received svc stop/shutdown request") callback.Do(stopFunction) }) } @@ -87,10 +88,11 @@ func withCPUProfile() bool { return *cpuprofile != "" } // BeforeRun takes care of necessary actions such as creating files // before the beat should run. func BeforeRun() { + var logger = logp.NewLogger("service") if withCPUProfile() { cpuOut, err := os.Create(*cpuprofile) if err != nil { - logp.Err("Failed to create CPU profile: %v", err) + logger.Errorf("Failed to create CPU profile: %v", err) os.Exit(1) } pprof.StartCPUProfile(cpuOut) @@ -100,7 +102,7 @@ func BeforeRun() { return } - logp.Info("Start pprof endpoint") + logger.Info("Start pprof endpoint") mux := http.NewServeMux() // Register pprof handler @@ -114,14 +116,14 @@ func BeforeRun() { // Ensure we are listening before returning listener, err := net.Listen("tcp", *httpprof) if err != nil { - logp.Err("Failed to start stats listener: %v", err) + logger.Errorf("Failed to start pprof listener: %v", err) os.Exit(1) } go func() { // Serve returns always a non-nil error err := http.Serve(listener, mux) - logp.Info("Finished pprof endpoint: %v", err) + logger.Infof("Finished pprof endpoint: %v", err) }() } @@ -153,6 +155,7 @@ func metricsHandler(w http.ResponseWriter, r *http.Request) { // Cleanup handles cleaning up the runtime and OS environments. This includes // tasks such as stopping the CPU profile if it is running. func Cleanup() { + var logger = logp.NewLogger("service") if withCPUProfile() { pprof.StopCPUProfile() cpuOut.Close() @@ -163,25 +166,29 @@ func Cleanup() { writeHeapProfile(*memprofile) - debugMemStats() + debugMemStats(logger.Named("mem")) } } -func debugMemStats() { +func debugMemStats(logger *logp.Logger) { + if !logger.IsDebug() { + return + } var m runtime.MemStats runtime.ReadMemStats(&m) - logp.Debug("mem", "Memory stats: In use: %d Total (even if freed): %d System: %d", + logger.Debug("Memory stats: In use: %d Total (even if freed): %d System: %d", m.Alloc, m.TotalAlloc, m.Sys) } func writeHeapProfile(filename string) { + var logger = logp.NewLogger("service") f, err := os.Create(filename) if err != nil { - logp.Err("Failed creating file %s: %s", filename, err) + logger.Errorf("Failed creating file %s: %s", filename, err) return } pprof.WriteHeapProfile(f) f.Close() - logp.Info("Created memory profile file %s.", filename) + logger.Infof("Created memory profile file %s.", filename) } From 2c8252b2d197914c4ba3fda070e0dacb48b85eec Mon Sep 17 00:00:00 2001 From: Jaime Soriano Pastor Date: Tue, 17 Mar 2020 17:08:16 +0100 Subject: [PATCH 5/5] Nit. Don't use var --- libbeat/service/service.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/libbeat/service/service.go b/libbeat/service/service.go index 84c017b3587..ec6e0fca672 100644 --- a/libbeat/service/service.go +++ b/libbeat/service/service.go @@ -41,7 +41,7 @@ import ( // the service shut downs gracefully. func HandleSignals(stopFunction func(), cancel context.CancelFunc) { var callback sync.Once - var logger = logp.NewLogger("service") + logger := logp.NewLogger("service") // On termination signals, gracefully stop the Beat sigc := make(chan os.Signal, 1) @@ -88,7 +88,7 @@ func withCPUProfile() bool { return *cpuprofile != "" } // BeforeRun takes care of necessary actions such as creating files // before the beat should run. func BeforeRun() { - var logger = logp.NewLogger("service") + logger := logp.NewLogger("service") if withCPUProfile() { cpuOut, err := os.Create(*cpuprofile) if err != nil { @@ -155,7 +155,7 @@ func metricsHandler(w http.ResponseWriter, r *http.Request) { // Cleanup handles cleaning up the runtime and OS environments. This includes // tasks such as stopping the CPU profile if it is running. func Cleanup() { - var logger = logp.NewLogger("service") + logger := logp.NewLogger("service") if withCPUProfile() { pprof.StopCPUProfile() cpuOut.Close() @@ -181,7 +181,7 @@ func debugMemStats(logger *logp.Logger) { } func writeHeapProfile(filename string) { - var logger = logp.NewLogger("service") + logger := logp.NewLogger("service") f, err := os.Create(filename) if err != nil { logger.Errorf("Failed creating file %s: %s", filename, err)