Merge pull request #6 from MrAlias/log-level

Unify logging

CHANGELOG.md

@@ -8,6 +8,19 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/).
 ### Added
 
 *   Travis CI configuration to validate and build this project.
+*   A `--log-level` command flag to specify the user desired minimum logging level.
+*   A `log` package to unify the adapter logging function.
+
+### Changed
+
+*   Switched to using the upstream [New Relic Go telemetry SDK](https://github.com/newrelic/newrelic-telemetry-sdk-go) instead of the internal `nrsdk` package.
+*   Unified the adapter logging. Logs should now have a unified format and be configurable globaly to set the logging level.
+*   The `metric.BuildHandler` and `trace.BuildHandler` functions no longer take an Istio adapter `Logger` interface as an argument.
+*   The helm-charts now have a `logLevel` value to specify the adapter logging level during the deploy.
+
+### Removed
+
+*   The `--debug` command flag is now replaced by setting the `--log-level` flag to `debug`.
 
 ## 1.0.0
 

DEVELOPMENT.md

@@ -59,7 +59,7 @@ Another option is to export an environment variable (`NEW_RELIC_API_KEY`) prior
 ```shell
 go run cmd/main.go \
   --cluster-name "Local Testing" \
-  --debug \
+  --log-level debug \
   "$NEW_RELIC_API_KEY"
 ```
 
@@ -109,7 +109,8 @@ $MIXC report \
   --bytes_attributes source.ip=c0:0:0:2
 ```
 
-The `newrelic-istio-adapter` should output activity to `STDOUT` signifying that metrics have been captured and sent to New Relic.
+If you set the `--log-level` option to `debug` when running the `newrelic-istio-adapter` you should start to see logs describing how the `newrelic-istio-adapter` is receiving metrics and also sending those metrics to New Relic.
+The default logging level (`error`) will not display this information in the logs, but should log any errors if the `newrelic-istio-adapter` is not operating correctly.
 
 ## Release Process
 

README.md

@@ -126,7 +126,17 @@ As an example, this Insights query will display a timeseries graph of total Isti
 From Metric SELECT sum(istio.request.total) TIMESERIES
 ```
 
-The logs of Mixer and the `newrelic-istio-adapter` in Kubernetes should show activity or errors.
+By default, Mixer is configured to output `info` level logs.
+This should include logs about telemetry events being sent to the `newrelic-istio-adapter`.
+Be sure to verify this is happening.
+
+```shell
+kubectl -n istio-system logs -l app=istio-mixer
+```
+
+Additionally, the `newrelic-istio-adapter` logs should be empty.
+By default the `newrelic-istio-adapter` only logs errors.
+Be sure to also verify this.
 
 ```shell
 kubectl -n newrelic-istio-adapter logs -l app.kubernetes.io/name=newrelic-istio-adapter

cmd/main.go

@@ -25,6 +25,7 @@ import (
 	"syscall"
 
 	newrelic "github.com/newrelic/newrelic-istio-adapter"
+	"github.com/newrelic/newrelic-istio-adapter/log"
 	"github.com/newrelic/newrelic-telemetry-sdk-go/telemetry"
 	"google.golang.org/grpc"
 	"google.golang.org/grpc/credentials"
@@ -38,7 +39,7 @@ var Version = "undefined"
 var (
 	portPtr          = kingpin.Flag("port", "port gRPC server listens on").Default("55912").OverrideDefaultFromEnvar("NEW_RELIC_PORT").Short('p').Int32()
 	clusterNamePtr   = kingpin.Flag("cluster-name", "Name of cluster where metrics come from").OverrideDefaultFromEnvar("NEW_RELIC_CLUSTER_NAME").String()
-	debugPtr         = kingpin.Flag("debug", "enable debug logging").OverrideDefaultFromEnvar("NEW_RELIC_DEBUG").Short('d').Bool()
+	logLevelPtr      = kingpin.Flag("log-level", "set logging level").OverrideDefaultFromEnvar("NEW_RELIC_LOG_LEVEL").Default("error").Enum(log.Levels()...)
 	harvestPeriodPtr = kingpin.Flag("harvest-period", "rate data is reported to New Relic").Default("5s").OverrideDefaultFromEnvar("NEW_RELIC_HARVEST_PERIOD").Duration()
 	metricsHostPtr   = kingpin.Flag("metrics-host", "Endpoint to send metrics (used for debugging)").OverrideDefaultFromEnvar("NEW_RELIC_METRICS_HOST").String()
 	spansHostPtr     = kingpin.Flag("spans-host", "Endpoint to send spans (used for debugging)").OverrideDefaultFromEnvar("NEW_RELIC_SPANS_HOST").String()
@@ -78,32 +79,31 @@ func main() {
 	kingpin.Version(Version)
 	kingpin.Parse()
 
+	l, err := log.ParseLevel(*logLevelPtr)
+	if err != nil {
+		log.Fatalf("failed to configure logging: %v\n", err)
+	}
+	log.SetOutputLevel(l)
+
 	var commonAttrs map[string]interface{}
 	if clusterNamePtr != nil && *clusterNamePtr != "" {
 		commonAttrs = map[string]interface{}{
 			"cluster.name": *clusterNamePtr,
 		}
 	}
 
-	debugLogFile := ioutil.Discard
-	if *debugPtr {
-		debugLogFile = os.Stderr
-	}
-
 	h, err := telemetry.NewHarvester(
 		telemetry.ConfigAPIKey(*apiKeyPtr),
 		telemetry.ConfigCommonAttributes(commonAttrs),
-		telemetry.ConfigBasicErrorLogger(os.Stderr),
 		telemetry.ConfigHarvestPeriod(*harvestPeriodPtr),
-		telemetry.ConfigBasicDebugLogger(debugLogFile),
+		log.HarvesterConfigFunc(),
 		func(cfg *telemetry.Config) {
 			cfg.MetricsURLOverride = *metricsHostPtr
 			cfg.SpansURLOverride = *spansHostPtr
 		},
 	)
 	if err != nil {
-		fmt.Printf("Failed to create harvester: %v\n", err)
-		os.Exit(-1)
+		log.Fatalf("failed to create harvester: %v\n", err)
 	}
 
 	address := fmt.Sprintf(":%d", *portPtr)
@@ -112,16 +112,14 @@ func main() {
 	if *mtlsCertPtr != "" && *mtlsKeyPtr != "" {
 		so, err := getServerTLSOption(*mtlsCertPtr, *mtlsKeyPtr, *mtlsCAPtr)
 		if err != nil {
-			fmt.Printf("Unable to configure gRPC server TLS: %v\n", err)
-			os.Exit(-1)
+			log.Fatalf("failed to configure gRPC server TLS: %v\n", err)
 		}
 		s, err = newrelic.NewServer(address, h, so)
 	} else {
 		s, err = newrelic.NewServer(address, h)
 	}
 	if err != nil {
-		fmt.Printf("Unable to start server: %v\n", err)
-		os.Exit(-1)
+		log.Fatalf("failed to start server: %v\n", err)
 	}
 
 	// Termination handler.
@@ -130,16 +128,15 @@ func main() {
 	go func() {
 		select {
 		case <-term:
-			fmt.Println("Received SIGTERM, exiting gracefully...")
+			log.Infof("received SIGTERM, exiting gracefully...")
 			if err := s.Close(); err != nil {
-				fmt.Printf("%v\n", err)
+				log.Errorf("%v\n", err)
 			}
 		}
 	}()
 
 	s.Run()
 	if err := s.Wait(); err != nil {
-		fmt.Printf("%v\n", err)
-		os.Exit(1)
+		log.Fatalf("%v\n", err)
 	}
 }

helm-charts/templates/deployment.yaml

@@ -53,6 +53,10 @@ spec:
           args:
             - --cluster-name
             - {{ .Values.clusterName }}
+          {{- with .Values.logLevel }}
+            - --log-level
+            - {{ . }}
+          {{- end }}
           {{- with .Values.metricsHost }}
             - --metrics-host
             - {{ . }}

helm-charts/values.yaml

@@ -30,6 +30,10 @@ istioNamespace: istio-system
 # Corresponds to the cluster.name attribute of metrics.
 clusterName: istio-cluster
 
+# Logging level for the adapter.
+# Valid logging levels are: debug, info, warn, error, fatal, or none
+#logLevel: error
+
 # Override the New Relic Metrics API endpoint (used for debugging).
 #metricsHost: ""
 

log/default.go

@@ -0,0 +1,89 @@
+package log
+
+import (
+	"encoding/json"
+
+	"github.com/newrelic/newrelic-telemetry-sdk-go/telemetry"
+	iLog "istio.io/pkg/log"
+)
+
+const (
+	// AdapterScopeName is the default logging scope name for this adapter.
+	AdapterScopeName       = "newrelic"
+	defaultOutputLevel     = ErrorLevel
+	defaultStackTraceLevel = NoneLevel
+)
+
+var adapterScope = iLog.RegisterScope(AdapterScopeName, "New Relic adapter logging messages.", 0)
+
+func init() {
+	adapterScope.SetOutputLevel(defaultOutputLevel.istioLevel())
+	adapterScope.SetStackTraceLevel(defaultStackTraceLevel.istioLevel())
+
+	// Configure the default Istio logger with our default options.
+	// This ensures things like gRPC logging (which is overriden by the
+	// Istio log package) is configured at the appropriate level.
+	opts := iLog.DefaultOptions()
+	opts.SetOutputLevel(iLog.DefaultScopeName, defaultOutputLevel.istioLevel())
+	opts.SetStackTraceLevel(iLog.DefaultScopeName, defaultStackTraceLevel.istioLevel())
+	_ = iLog.Configure(opts)
+}
+
+// Fatalf uses fmt.Sprintf to construct and log a message at fatal level.
+func Fatalf(template string, args ...interface{}) {
+	adapterScope.Fatalf(template, args...)
+}
+
+// Errorf uses fmt.Sprintf to construct and log a message at error level.
+func Errorf(template string, args ...interface{}) {
+	adapterScope.Errorf(template, args...)
+}
+
+// Warnf uses fmt.Sprintf to construct and log a message at warn level.
+func Warnf(template string, args ...interface{}) {
+	adapterScope.Warnf(template, args...)
+}
+
+// Infof uses fmt.Sprintf to construct and log a message at info level.
+func Infof(template string, args ...interface{}) {
+	adapterScope.Infof(template, args...)
+}
+
+// Debugf uses fmt.Sprintf to construct and log a message at debug level.
+func Debugf(template string, args ...interface{}) {
+	adapterScope.Debugf(template, args...)
+}
+
+// SetOutputLevel adjusts the output level associated with the adapter scope.
+func SetOutputLevel(l Level) {
+	adapterScope.SetOutputLevel(l.istioLevel())
+}
+
+// SetStackTraceLevel adjusts the stack tracing level associated with the adapter scope.
+func SetStackTraceLevel(l Level) {
+	adapterScope.SetStackTraceLevel(l.istioLevel())
+}
+
+// telemetryLogger returns a suitable telemetry.Harvester logging function
+func telemetryLogger(logf func(string, ...interface{})) func(map[string]interface{}) {
+	return func(fields map[string]interface{}) {
+		if js, err := json.Marshal(fields); nil != err {
+			logf("%s", err.Error())
+		} else {
+			logf("%s", string(js))
+		}
+	}
+}
+
+// HarvesterConfigFunc returns a configuration function for the telemetry Harvester initialization.
+//
+// There is not a one-to-one mapping of our/Istio logging levels to the telemetry package.
+// The mapping made here is that error logging is at the ErrorLevel, debug logging is at
+// the InfoLevel, and audit logging is at the DebugLevel.
+func HarvesterConfigFunc() func(*telemetry.Config) {
+	return func(cfg *telemetry.Config) {
+		cfg.ErrorLogger = telemetryLogger(adapterScope.Errorf)
+		cfg.DebugLogger = telemetryLogger(adapterScope.Infof)
+		cfg.AuditLogger = telemetryLogger(adapterScope.Debugf)
+	}
+}

log/level.go

@@ -0,0 +1,86 @@
+package log
+
+import (
+	"fmt"
+
+	iLog "istio.io/pkg/log"
+)
+
+// Level of logging severity
+type Level int
+
+const (
+	// InvalidLevel represents an invalid logging level returned when parsing errors occur.
+	InvalidLevel Level = iota
+
+	// DebugLevel signifies all messages with debug level and above should be logged.
+	DebugLevel
+
+	// InfoLevel signifies all messages with info level and above should be logged.
+	InfoLevel
+
+	// WarnLevel signifies all messages with warn level and above should be logged.
+	WarnLevel
+
+	// ErrorLevel signifies all messages with error level and above should be logged.
+	ErrorLevel
+
+	// FatalLevel signifies only fatal level messages should be logged.
+	FatalLevel
+
+	// NoneLevel signifies no messages be logged.
+	NoneLevel
+)
+
+var stringToLevel = map[string]Level{
+	"debug": DebugLevel,
+	"info":  InfoLevel,
+	"warn":  WarnLevel,
+	"error": ErrorLevel,
+	"fatal": FatalLevel,
+	"none":  NoneLevel,
+}
+
+var levelToString = map[Level]string{
+	DebugLevel: "debug",
+	InfoLevel:  "info",
+	WarnLevel:  "warn",
+	ErrorLevel: "error",
+	FatalLevel: "fatal",
+	NoneLevel:  "none",
+}
+
+var levelToIstioLevel = map[Level]iLog.Level{
+	DebugLevel: iLog.DebugLevel,
+	InfoLevel:  iLog.InfoLevel,
+	WarnLevel:  iLog.WarnLevel,
+	ErrorLevel: iLog.ErrorLevel,
+	FatalLevel: iLog.FatalLevel,
+	NoneLevel:  iLog.NoneLevel,
+}
+
+// ParseLevel interprets level name as a Level.
+func ParseLevel(name string) (Level, error) {
+	if s, ok := stringToLevel[name]; ok {
+		return s, nil
+	}
+	return InvalidLevel, fmt.Errorf("invalid log level: %s", name)
+}
+
+// String returns Level string representation.
+func (l Level) String() string {
+	return levelToString[l]
+}
+
+func (l Level) istioLevel() iLog.Level {
+	return levelToIstioLevel[l]
+}
+
+// Levels returns all valid level names.
+func Levels() []string {
+	l := make([]string, 0, len(stringToLevel))
+	for k := range stringToLevel {
+		l = append(l, k)
+	}
+	return l
+}

metric/builder.go

@@ -21,6 +21,7 @@ import (
 	"unicode/utf16"
 
 	"github.com/newrelic/newrelic-istio-adapter/config"
+	"github.com/newrelic/newrelic-istio-adapter/log"
 	"github.com/newrelic/newrelic-telemetry-sdk-go/telemetry"
 	"istio.io/istio/mixer/pkg/adapter"
 )
@@ -37,15 +38,14 @@ type metricConfig struct {
 }
 
 // BuildHandler returns a metric Handler with valid configuration.
-func BuildHandler(params *config.Params, h *telemetry.Harvester, env adapter.Env) (*Handler, error) {
+func BuildHandler(params *config.Params, h *telemetry.Harvester) (*Handler, error) {
 	cfg, err := buildConfig(params)
 	if err != nil {
 		return nil, err
 	}
-	env.Logger().Infof("Built metrics: %#v", cfg.metrics)
+	log.Infof("built metrics: %#v", cfg.metrics)
 
 	handler := &Handler{
-		logger:  env.Logger(),
 		agg:     h.MetricAggregator(),
 		metrics: cfg.metrics,
 	}

metric/builder_test.go

@@ -18,8 +18,6 @@ import (
 	"strings"
 	"testing"
 
-	adapterTest "istio.io/istio/mixer/pkg/adapter/test"
-
 	"github.com/newrelic/newrelic-istio-adapter/config"
 )
 
@@ -97,8 +95,7 @@ func TestBuildHandler(t *testing.T) {
 			Metrics:   map[string]*config.Params_MetricInfo{mixerMetricName: pmi},
 		}
 
-		env := adapterTest.NewEnv(t)
-		h, err := BuildHandler(params, nil, env)
+		h, err := BuildHandler(params, nil)
 
 		// Invalid name, but we saw expected error, so it's all good.
 		if !tc.isValid && err != nil {