Log total non-zero expvars on shutdown (#2349)

Replaces the similar functionality from Metricbeat and Winlogbeat,
generalizing it to all Beats. Part of #1931.

CHANGELOG.asciidoc

@@ -71,7 +71,8 @@ https://github.com/elastic/beats/compare/v5.0.0-alpha5...master[Check the HEAD d
 - Enhance contains condition to work on fields that are arrays of strings. {issue}2237[2237]
 - Lookup the configuration file relative to the `-path.config` CLI flag. {pull}2245[2245]
 - Re-write import_dashboards.sh in Golang. {pull}2155[2155]
-- Update to Go 1.7 {pull}2306[2306]
+- Update to Go 1.7. {pull}2306[2306]
+- Log total non-zero internal metrics on shutdown. {pull}2349[2349]
 
 *Metricbeat*
 

filebeat/filebeat.full.yml

@@ -751,7 +751,8 @@ output.elasticsearch:
 
 # If enabled, filebeat periodically logs its internal metrics that have changed
 # in the last period. For each metric that changed, the delta from the value at
-# the beginning of the period is logged. The default is true.
+# the beginning of the period is logged. Also, the total values for
+# all non-zero internal metrics are logged on shutdown. The default is true.
 #logging.metrics.enabled: true
 
 # The period after which to log the internal metrics. The default is 30s.

libbeat/_meta/config.full.yml

@@ -531,7 +531,8 @@ output.elasticsearch:
 
 # If enabled, beatname periodically logs its internal metrics that have changed
 # in the last period. For each metric that changed, the delta from the value at
-# the beginning of the period is logged. The default is true.
+# the beginning of the period is logged. Also, the total values for
+# all non-zero internal metrics are logged on shutdown. The default is true.
 #logging.metrics.enabled: true
 
 # The period after which to log the internal metrics. The default is 30s.

libbeat/beat/beat.go

@@ -203,6 +203,7 @@ func (b *Beat) launch(bt Creator) error {
 
 	logp.Info("%s start running.", b.Name)
 	defer logp.Info("%s stopped.", b.Name)
+	defer logp.LogTotalExpvars(&b.Config.Logging)
 
 	return beater.Run(b)
 }

libbeat/docs/loggingconfig.asciidoc

@@ -69,7 +69,8 @@ the debug log level).
 
 If enabled, {beatname_uc} periodically logs its internal metrics that have
 changed in the last period. For each metric that changed, the delta from the
-value at the beginning of the period is logged. The default is true.
+value at the beginning of the period is logged. Also, the total values for
+all non-zero internal metrics are logged on shutdown. The default is true.
 
 Here is an example log line:
 

libbeat/logp/logp.go

@@ -224,3 +224,14 @@ func logExpvars(metricsCfg *LoggingMetricsConfig) {
 		}
 	}
 }
+
+func LogTotalExpvars(cfg *Logging) {
+	if cfg.Metrics.Enabled != nil && *cfg.Metrics.Enabled == false {
+		return
+	}
+	vals := map[string]int64{}
+	prevVals := map[string]int64{}
+	snapshotExpvars(vals)
+	metrics := buildMetricsOutput(prevVals, vals)
+	Info("Total non-zero values: %s", metrics)
+}

libbeat/tests/system/test_base.py

@@ -156,3 +156,6 @@ def test_logging_metrics(self):
             lambda: self.log_contains("No non-zero metrics in the last 100ms"),
             max_timeout=2)
         proc.check_kill_and_wait()
+        self.wait_until(
+            lambda: self.log_contains("Total non-zero values:"),
+            max_timeout=2)

metricbeat/beater/metricbeat.go

@@ -1,7 +1,6 @@
 package beater
 
 import (
-	"expvar"
 	"sync"
 
 	"github.com/elastic/beats/libbeat/beat"
@@ -49,7 +48,6 @@ func New(b *beat.Beat, rawConfig *common.Config) (beat.Beater, error) {
 // that a single unresponsive host cannot inadvertently block other hosts
 // within the same Module and MetricSet from collection.
 func (bt *Metricbeat) Run(b *beat.Beat) error {
-	defer dumpMetrics()
 
 	bt.client = b.Publisher.Connect()
 
@@ -84,13 +82,3 @@ func (bt *Metricbeat) Stop() {
 	bt.client.Close()
 	close(bt.done)
 }
-
-// dumpMetrics is used to log metrics on shutdown.
-func dumpMetrics() {
-	logp.Info("Dumping runtime metrics...")
-	expvar.Do(func(kv expvar.KeyValue) {
-		if kv.Key != "memstats" {
-			logp.Info("%s=%s", kv.Key, kv.Value.String())
-		}
-	})
-}

metricbeat/metricbeat.full.yml

@@ -715,7 +715,8 @@ output.elasticsearch:
 
 # If enabled, metricbeat periodically logs its internal metrics that have changed
 # in the last period. For each metric that changed, the delta from the value at
-# the beginning of the period is logged. The default is true.
+# the beginning of the period is logged. Also, the total values for
+# all non-zero internal metrics are logged on shutdown. The default is true.
 #logging.metrics.enabled: true
 
 # The period after which to log the internal metrics. The default is 30s.

packetbeat/packetbeat.full.yml

@@ -977,7 +977,8 @@ output.elasticsearch:
 
 # If enabled, packetbeat periodically logs its internal metrics that have changed
 # in the last period. For each metric that changed, the delta from the value at
-# the beginning of the period is logged. The default is true.
+# the beginning of the period is logged. Also, the total values for
+# all non-zero internal metrics are logged on shutdown. The default is true.
 #logging.metrics.enabled: true
 
 # The period after which to log the internal metrics. The default is 30s.

winlogbeat/beater/winlogbeat.go

@@ -138,7 +138,6 @@ func (eb *Winlogbeat) Run(b *beat.Beat) error {
 	if err := eb.setup(b); err != nil {
 		return err
 	}
-	defer eb.cleanup(b)
 
 	persistedState := eb.checkpoint.States()
 
@@ -164,20 +163,6 @@ func (eb *Winlogbeat) Run(b *beat.Beat) error {
 	return nil
 }
 
-// cleanup attempts to remove any files or data it may have created which should
-// not be persisted.
-func (eb *Winlogbeat) cleanup(b *beat.Beat) {
-	logp.Info("Dumping runtime metrics...")
-	expvar.Do(func(kv expvar.KeyValue) {
-		logf := logp.Info
-		if kv.Key == "memstats" {
-			logf = memstatsf
-		}
-
-		logf("%s=%s", kv.Key, kv.Value.String())
-	})
-}
-
 // Stop is used to tell the winlogbeat that it should cease executing.
 func (eb *Winlogbeat) Stop() {
 	logp.Info("Stopping Winlogbeat")

winlogbeat/winlogbeat.full.yml

@@ -566,7 +566,8 @@ output.elasticsearch:
 
 # If enabled, winlogbeat periodically logs its internal metrics that have changed
 # in the last period. For each metric that changed, the delta from the value at
-# the beginning of the period is logged. The default is true.
+# the beginning of the period is logged. Also, the total values for
+# all non-zero internal metrics are logged on shutdown. The default is true.
 #logging.metrics.enabled: true
 
 # The period after which to log the internal metrics. The default is 30s.