Add support to suppress tls logging (#157)

- Allow a way to suppress the logging messages related to tls handshake error
logged in https://cs.opensource.google/go/go/+/master:src/net/http/server.go;l=1933?q=%22TLS%20handshake%20error%20from%20%22&ss=go%2Fgo.
- Remove unused anomaly logger method

Author: agbpatro

README.md

@@ -165,6 +165,10 @@ Configure and use Prometheus or a StatsD-interface supporting data store for met
 
 ![Basic Dashboard](./doc/grafana-dashboard.png)
 
+## Logging
+
+To suppress [tls handshake error logging](https://cs.opensource.google/go/go/+/master:src/net/http/server.go;l=1933?q=%22TLS%20handshake%20error%20from%20%22&ss=go%2Fgo), set environment variable `SUPPRESS_TLS_HANDSHAKE_ERROR_LOGGING` to `true`. See [docker compose](./docker-compose.yml) for example.
+
 ## Protos
 Data is encapsulated into protobuf messages of different types. Protos can be recompiled via:
 

config/config_initializer.go

@@ -3,6 +3,7 @@ package config
 import (
 	"encoding/json"
 	"flag"
+	"log"
 	"os"
 
 	"github.com/sirupsen/logrus/hooks/test"
@@ -15,7 +16,11 @@ import (
 // LoadApplicationConfiguration loads the configuration from args and config files
 func LoadApplicationConfiguration() (config *Config, logger *logrus.Logger, err error) {
 
-	logger = logrus.NewBasicLogrusLogger("fleet-telemetry")
+	logger, err = logrus.NewBasicLogrusLogger("fleet-telemetry")
+	if err != nil {
+		return nil, nil, err
+	}
+	log.SetOutput(logger)
 
 	configFilePath := loadConfigFlags()
 
@@ -38,9 +43,15 @@ func loadApplicationConfig(configFilePath string) (*Config, error) {
 
 	config := &Config{}
 	err = json.NewDecoder(configFile).Decode(&config)
+	if err != nil {
+		return nil, err
+	}
 
 	log, _ := test.NewNullLogger()
-	logger := logrus.NewLogrusLogger("null_logger", map[string]interface{}{}, log.WithField("context", "metrics"))
+	logger, err := logrus.NewLogrusLogger("null_logger", map[string]interface{}{}, log.WithField("context", "metrics"))
+	if err != nil {
+		return nil, err
+	}
 	config.MetricCollector = metrics.NewCollector(config.Monitoring, logger)
 
 	config.AckChan = make(chan *telemetry.Record)

docker-compose.yml

@@ -23,6 +23,7 @@ services:
       AWS_ACCESS_KEY_ID: ABC123
       AWS_SECRET_ACCESS_KEY: EFG456
       PUBSUB_EMULATOR_HOST: pubsub:8085
+      SUPPRESS_TLS_HANDSHAKE_ERROR_LOGGING: true
     depends_on:
       kinesis:
         condition: service_healthy

logger/logger.go

@@ -2,6 +2,8 @@ package logrus
 
 import (
 	"os"
+	"strconv"
+	"strings"
 
 	"github.com/mattn/go-colorable"
 	"github.com/sirupsen/logrus"
@@ -19,6 +21,10 @@ const (
 	FATAL
 )
 
+const (
+	tlsFilter = "http: TLS handshake error from"
+)
+
 // AllLogType is a map of LogType to string names
 var AllLogType = map[LogType]string{
 	DEBUG: "debug",
@@ -34,29 +40,43 @@ type LogInfo map[string]interface{}
 // Logger a logrus implementer of the JSON logger interface
 type Logger struct {
 	logger *logrus.Entry
+
+	suppressionFilter string
 }
 
 // NewLogrusLogger return a LogrusLogger
-func NewLogrusLogger(context string, info LogInfo, logger *logrus.Entry) *Logger {
+func NewLogrusLogger(context string, info LogInfo, logger *logrus.Entry) (*Logger, error) {
 	if logger == nil {
 		logger = logrus.WithField("context", context)
 	}
-
 	l := &Logger{logger: logger}
 	l.logger = l.getEntry(info)
-	return l
+	value, ok := os.LookupEnv("SUPPRESS_TLS_HANDSHAKE_ERROR_LOGGING")
+	if ok {
+		b, err := strconv.ParseBool(value)
+		if err != nil {
+			return nil, err
+		}
+		if b {
+			l.suppressionFilter = tlsFilter
+		}
+	}
+	return l, nil
 }
 
 // NewBasicLogrusLogger creates a logrus logger with a context but no other options
-func NewBasicLogrusLogger(context string) *Logger {
+func NewBasicLogrusLogger(context string) (*Logger, error) {
 	return NewLogrusLogger(context, nil, nil)
 }
 
 // NewColorLogrusLogger creates a logrus logger with a context and colorized output support
-func NewColorLogrusLogger(context string) *Logger {
-	logger := NewLogrusLogger(context, nil, nil)
+func NewColorLogrusLogger(context string) (*Logger, error) {
+	logger, err := NewLogrusLogger(context, nil, nil)
+	if err != nil {
+		return nil, err
+	}
 	logger.SetColorFormatter(true)
-	return logger
+	return logger, nil
 }
 
 // Set minimum log level for messages
@@ -69,8 +89,18 @@ func SetLogLevel(name string) {
 	logrus.SetLevel(level)
 }
 
+func (l *Logger) shouldSuppress(message string) bool {
+	if l.suppressionFilter == "" {
+		return false
+	}
+	return strings.Contains(message, l.suppressionFilter)
+}
+
 // Log logs a message on a particular log level
 func (l *Logger) Log(logType LogType, message string, info LogInfo) {
+	if l.shouldSuppress(message) {
+		return
+	}
 	entry := l.getEntry(info)
 
 	switch logType {
@@ -87,13 +117,22 @@ func (l *Logger) Log(logType LogType, message string, info LogInfo) {
 	}
 }
 
+// Write implements the Write method of the io.Writer interface
+func (l *Logger) Write(p []byte) (n int, err error) {
+	l.ActivityLog(string(p), nil)
+	return len(p), nil
+}
+
 // Print allows Printing on the logger
 func (l *Logger) Print(v ...interface{}) {
 	l.logger.Print(v...)
 }
 
 // Printf allows Printf'ing on the logger
 func (l *Logger) Printf(format string, v ...interface{}) {
+	if l.shouldSuppress(format) {
+		return
+	}
 	l.logger.Printf(format, v...)
 }
 
@@ -104,33 +143,30 @@ func (l *Logger) Println(v ...interface{}) {
 
 // Fatalf allows Fatalf'ing on the logger
 func (l *Logger) Fatalf(format string, v ...interface{}) {
+	if l.shouldSuppress(format) {
+		return
+	}
 	l.logger.Fatalf(format, v...)
 }
 
 // ActivityLog is used for web activity logs
 func (l *Logger) ActivityLog(message string, info LogInfo) {
+	if l.shouldSuppress(message) {
+		return
+	}
 	entry := l.getEntry(info)
 	entry.WithField("activity", true).Info(message)
 }
 
-// AnomalyLog is used to tag a log line as an anomaly
-func (l *Logger) AnomalyLog(message string, info LogInfo) {
-	entry := l.getEntry(info)
-	entry.WithField("anomaly", true).Error(message)
-}
-
 // ErrorLog log an error message
 func (l *Logger) ErrorLog(message string, err error, info LogInfo) {
+	if l.shouldSuppress(message) {
+		return
+	}
 	entry := l.getEntry(info)
 	entry.WithError(err).Error(message)
 }
 
-// AnomalyLogError log an error that is an anomaly
-func (l *Logger) AnomalyLogError(message string, err error, info LogInfo) {
-	entry := l.getEntry(info)
-	entry.WithError(err).WithField("anomaly", true).Error(message)
-}
-
 // SetJSONFormatter sets logger to emit JSON or false => TextFormatter
 func (l *Logger) SetJSONFormatter(json bool) {
 	if json {

logger/logger_logrus_test.go

@@ -2,6 +2,7 @@ package logrus
 
 import (
 	"errors"
+	"os"
 
 	githubLogrus "github.com/sirupsen/logrus"
 
@@ -10,29 +11,58 @@ import (
 )
 
 var _ = Describe("logger tests", func() {
+
+	BeforeEach(func() {
+		os.Clearenv()
+	})
+
 	It("works", func() {
 		data := map[string]interface{}{"simple": "value", "complex": `has "quotes" and spaces`, "boolean": true}
 
 		logger, hook := NoOpLogger()
 
 		logger.Log(INFO, "http", data)
-		Expect(len(hook.Entries)).To(Equal(1))
+		Expect(hook.Entries).To(HaveLen(1))
 		Expect(hook.LastEntry().Level).To(Equal(githubLogrus.InfoLevel))
 		Expect(hook.LastEntry().Message).To(Equal("http"))
 
 		logger.ActivityLog("sample_activity_log", data)
-		Expect(len(hook.Entries)).To(Equal(2))
+		Expect(hook.Entries).To(HaveLen(2))
 		Expect(hook.LastEntry().Level).To(Equal(githubLogrus.InfoLevel))
 		Expect(hook.LastEntry().Message).To(Equal("sample_activity_log"))
 
-		logger.AnomalyLog("sample_anomaly_log", data)
-		Expect(len(hook.Entries)).To(Equal(3))
+		logger.ErrorLog("sample_anomaly_log", nil, data)
+		Expect(hook.Entries).To(HaveLen(3))
 		Expect(hook.LastEntry().Level).To(Equal(githubLogrus.ErrorLevel))
 		Expect(hook.LastEntry().Message).To(Equal("sample_anomaly_log"))
 
-		logger.AnomalyLogError("sample_anomaly_log_2", errors.New("error message"), nil)
-		Expect(len(hook.Entries)).To(Equal(4))
+		logger.ErrorLog("sample_anomaly_log_2", errors.New("error message"), nil)
+		Expect(hook.Entries).To(HaveLen(4))
 		Expect(hook.LastEntry().Level).To(Equal(githubLogrus.ErrorLevel))
 		Expect(hook.LastEntry().Message).To(Equal("sample_anomaly_log_2"))
+
+		logger.Log(ERROR, "http: TLS handshake error from 0.0.0.0:1: EOF", nil)
+		Expect(hook.Entries).To(HaveLen(5))
+		Expect(hook.LastEntry().Level).To(Equal(githubLogrus.ErrorLevel))
+		Expect(hook.LastEntry().Message).To(Equal("http: TLS handshake error from 0.0.0.0:1: EOF"))
 	})
+
+	Context("Tls handshake error", func() {
+		DescribeTable("suppresses",
+			func(envValue string) {
+				os.Setenv("SUPPRESS_TLS_HANDSHAKE_ERROR_LOGGING", envValue)
+				logger, hook := NoOpLogger()
+				logger.Log(ERROR, "http: TLS handshake error from 0.0.0.0:1: EOF", nil)
+				Expect(hook.Entries).To(BeEmpty())
+				logger.Log(ERROR, "Random error", nil)
+				Expect(hook.Entries).To(HaveLen(1))
+				Expect(hook.LastEntry().Message).To(Equal("Random error"))
+
+			},
+			Entry("for env variable true", "true"),
+			Entry("for env variable TRUE", "TRUE"),
+			Entry("for env variable 1", "1"),
+		)
+	})
+
 })

logger/no_op_logger.go

@@ -6,5 +6,6 @@ import (
 
 func NoOpLogger() (*Logger, *test.Hook) {
 	log, hook := test.NewNullLogger()
-	return NewLogrusLogger("null_logger", map[string]interface{}{}, log.WithField("context", "test")), hook
+	logger, _ := NewLogrusLogger("null_logger", map[string]interface{}{}, log.WithField("context", "test"))
+	return logger, hook
 }