Merge pull request #7 from DataDog/darcy.rayner/debug-logging

Darcy.rayner/debug logging

Author: DarcyRaynerDD

README.md

@@ -8,13 +8,19 @@ Datadog's Lambda Go client library enables distributed tracing between serverful
 go get github.com/DataDog/datadog-lambda-go
 ```
 
-The following Datadog environment variables should be defined via the AWS CLI or Serverless Framework:
+You can set the following environment variables via the AWS CLI or Serverless Framework
 
-- DD_API_KEY
+### DD_API_KEY
 
-Set the following Datadog environment variable to `datadoghq.eu` to send your data to the Datadog EU site.
+Your datadog API key
 
-- DD_SITE
+### DD_SITE
+
+Which Datadog site to use. Set this to `datadoghq.eu` to send your data to the Datadog EU site.
+
+### DD_LOG_LEVEL
+
+How much logging datadog-lambda-go should do. Set this to "debug" for extensive logs.
 
 ## Usage
 
@@ -35,7 +41,6 @@ func main() {
   lambda.Start(ddlambda.WrapHandler(myHandler, &ddlambda.Config{
     BatchInterval: time.Seconds * 15
     APIKey: "my-api-key",
-    AppKey: "my-app-key",
   }))
   */
 }

ddlambda.go

@@ -14,8 +14,10 @@ import (
 	"net/http"
 	"os"
 	"runtime"
+	"strings"
 	"time"
 
+	"github.com/DataDog/datadog-lambda-go/internal/logger"
 	"github.com/DataDog/datadog-lambda-go/internal/metrics"
 	"github.com/DataDog/datadog-lambda-go/internal/trace"
 	"github.com/DataDog/datadog-lambda-go/internal/wrapper"
@@ -35,6 +37,9 @@ type (
 		// Site is the host to send metrics to. If empty, this value is read from the 'DD_SITE' environment variable, or if that is empty
 		// will default to 'datadoghq.com'.
 		Site string
+
+		// DebugLogging will turn on extended debug logging.
+		DebugLogging bool
 	}
 )
 
@@ -43,12 +48,24 @@ const (
 	DatadogAPIKeyEnvVar = "DD_API_KEY"
 	// DatadogSiteEnvVar is the environment variable that will be used as the API host.
 	DatadogSiteEnvVar = "DD_SITE"
+	// DatadogLogLevelEnvVar is the environment variable that will be used to check the log level.
+	// if it equals "debug" everything will be logged.
+	DatadogLogLevelEnvVar = "DD_LOG_LEVEL"
 )
 
 // WrapHandler is used to instrument your lambda functions, reading in context from API Gateway.
 // It returns a modified handler that can be passed directly to the lambda.Start function.
 func WrapHandler(handler interface{}, cfg *Config) interface{} {
 
+	logLevel := os.Getenv(DatadogLogLevelEnvVar)
+	if strings.EqualFold(logLevel, "debug") {
+		logger.SetLogLevel(logger.LevelDebug)
+	}
+
+	if cfg != nil && cfg.DebugLogging {
+		logger.SetLogLevel(logger.LevelDebug)
+	}
+
 	// Set up state that is shared between handler invocations
 	tl := trace.Listener{}
 	ml := metrics.MakeListener(cfg.toMetricsConfig())
@@ -79,6 +96,7 @@ func GetContext() context.Context {
 func DistributionWithContext(ctx context.Context, metric string, value float64, tags ...string) {
 	pr := metrics.GetProcessor(GetContext())
 	if pr == nil {
+		logger.Error(fmt.Errorf("couldn't get metrics processor from current context"))
 		return
 	}
 
@@ -91,6 +109,7 @@ func DistributionWithContext(ctx context.Context, metric string, value float64,
 		Values: []metrics.MetricValue{},
 	}
 	m.AddPoint(time.Now(), value)
+	logger.Debug(fmt.Sprintf("adding metric \"%s\", with value %f", metric, value))
 	pr.AddMetric(&m)
 }
 
@@ -115,9 +134,13 @@ func (cfg *Config) toMetricsConfig() metrics.Config {
 		mc.APIKey = os.Getenv(DatadogAPIKeyEnvVar)
 
 	}
+	if mc.APIKey == "" {
+		logger.Error(fmt.Errorf("couldn't read DD_API_KEY from environment"))
+	}
 	if mc.Site == "" {
 		mc.Site = os.Getenv(DatadogSiteEnvVar)
 	}
+
 	return mc
 }
 

internal/logger/log.go

@@ -0,0 +1,62 @@
+package logger
+
+import (
+	"encoding/json"
+	"fmt"
+	"log"
+)
+
+// LogLevel represents the level of logging that should be performed
+type LogLevel int
+
+const (
+	// LevelDebug logs all information
+	LevelDebug LogLevel = iota
+	// LevelError only logs errors
+	LevelError LogLevel = iota
+)
+
+var (
+	logLevel = LevelError
+)
+
+// SetLogLevel set the level of logging for the ddlambda
+func SetLogLevel(ll LogLevel) {
+	logLevel = ll
+}
+
+// Error logs a structured error message to stdout
+func Error(err error) {
+
+	type logStructure struct {
+		Status  string `json:"status"`
+		Message string `json:"message"`
+	}
+
+	finalMessage := logStructure{
+		Status:  "error",
+		Message: fmt.Sprintf("datadog: %s", err.Error()),
+	}
+	result, _ := json.Marshal(finalMessage)
+
+	log.Println(string(result))
+}
+
+// Debug logs a structured log message to stdout
+func Debug(message string) {
+	if logLevel > LevelDebug {
+		return
+	}
+	type logStructure struct {
+		Status  string `json:"status"`
+		Message string `json:"message"`
+	}
+	finalMessage := logStructure{
+		Status:  "debug",
+		Message: fmt.Sprintf("datadog: %s", message),
+	}
+
+	result, _ := json.Marshal(finalMessage)
+
+	log.Println(string(result))
+}

internal/metrics/api.go

@@ -13,7 +13,10 @@ import (
 	"context"
 	"encoding/json"
 	"fmt"
+	"io/ioutil"
 	"net/http"
+
+	"github.com/DataDog/datadog-lambda-go/internal/logger"
 )
 
 type (
@@ -70,14 +73,18 @@ func (cl *APIClient) SendMetrics(metrics []APIMetric) error {
 	}
 	body := bytes.NewBuffer(content)
 
-	req, err := http.NewRequest("POST", cl.makeRoute("series"), body)
+	// For the moment we only support distribution metrics.
+	// Other metric types use the "series" endpoint, which takes an identical payload.
+	req, err := http.NewRequest("POST", cl.makeRoute("distribution_points"), body)
 	if err != nil {
 		return fmt.Errorf("Couldn't create send metrics request:%v", err)
 	}
 	req = req.WithContext(cl.context)
 
 	defer req.Body.Close()
 
+	logger.Debug(fmt.Sprintf("Sending payload with body %s", content))
+
 	cl.addAPICredentials(req)
 
 	resp, err := cl.httpClient.Do(req)
@@ -87,8 +94,13 @@ func (cl *APIClient) SendMetrics(metrics []APIMetric) error {
 	}
 	defer resp.Body.Close()
 
-	if resp.StatusCode != http.StatusCreated {
-		return fmt.Errorf("Failed to send metrics to API. Status Code %d", resp.StatusCode)
+	if resp.StatusCode < 200 || resp.StatusCode > 299 {
+		bodyBytes, err := ioutil.ReadAll(resp.Body)
+		body := ""
+		if err == nil {
+			body = string(bodyBytes)
+		}
+		return fmt.Errorf("Failed to send metrics to API. Status Code %d, Body %s", resp.StatusCode, body)
 	}
 	return nil
 }
@@ -100,7 +112,9 @@ func (cl *APIClient) addAPICredentials(req *http.Request) {
 }
 
 func (cl *APIClient) makeRoute(route string) string {
-	return fmt.Sprintf("%s/%s", cl.baseAPIURL, route)
+	url := fmt.Sprintf("%s/%s", cl.baseAPIURL, route)
+	logger.Debug(fmt.Sprintf("posting to url %s", url))
+	return url
 }
 
 func marshalAPIMetricsModel(metrics []APIMetric) ([]byte, error) {

internal/metrics/api_test.go

@@ -53,8 +53,8 @@ func TestSendMetricsSuccess(t *testing.T) {
 		body, _ := ioutil.ReadAll(r.Body)
 		s := string(body)
 
-		assert.Equal(t, "/series?api_key=12345", r.URL.String())
-		assert.Equal(t, "{\"series\":[{\"metric\":\"metric-1\",\"tags\":[\"a\",\"b\",\"c\"],\"type\":\"distribution\",\"points\":[[1,2],[3,4],[5,6]]}]}", s)
+		assert.Equal(t, "/distribution_points?api_key=12345", r.URL.String())
+		assert.Equal(t, "{\"series\":[{\"metric\":\"metric-1\",\"tags\":[\"a\",\"b\",\"c\"],\"type\":\"distribution\",\"points\":[[1,[2]],[3,[4]],[5,[6]]]}]}", s)
 
 	}))
 	defer server.Close()
@@ -65,8 +65,10 @@ func TestSendMetricsSuccess(t *testing.T) {
 			Host:       nil,
 			Tags:       []string{"a", "b", "c"},
 			MetricType: DistributionType,
-			Points: [][]float64{
-				{float64(1), float64(2)}, {float64(3), float64(4)}, {float64(5), float64(6)},
+			Points: []interface{}{
+				[]interface{}{float64(1), []interface{}{float64(2)}},
+				[]interface{}{float64(3), []interface{}{float64(4)}},
+				[]interface{}{float64(5), []interface{}{float64(6)}},
 			},
 		},
 	}
@@ -86,8 +88,8 @@ func TestSendMetricsBadRequest(t *testing.T) {
 		body, _ := ioutil.ReadAll(r.Body)
 		s := string(body)
 
-		assert.Equal(t, "/series?api_key=12345", r.URL.String())
-		assert.Equal(t, "{\"series\":[{\"metric\":\"metric-1\",\"tags\":[\"a\",\"b\",\"c\"],\"type\":\"distribution\",\"points\":[[1,2],[3,4],[5,6]]}]}", s)
+		assert.Equal(t, "/distribution_points?api_key=12345", r.URL.String())
+		assert.Equal(t, "{\"series\":[{\"metric\":\"metric-1\",\"tags\":[\"a\",\"b\",\"c\"],\"type\":\"distribution\",\"points\":[[1,[2]],[3,[4]],[5,[6]]]}]}", s)
 
 	}))
 	defer server.Close()
@@ -98,8 +100,10 @@ func TestSendMetricsBadRequest(t *testing.T) {
 			Host:       nil,
 			Tags:       []string{"a", "b", "c"},
 			MetricType: DistributionType,
-			Points: [][]float64{
-				{float64(1), float64(2)}, {float64(3), float64(4)}, {float64(5), float64(6)},
+			Points: []interface{}{
+				[]interface{}{float64(1), []interface{}{float64(2)}},
+				[]interface{}{float64(3), []interface{}{float64(4)}},
+				[]interface{}{float64(5), []interface{}{float64(6)}},
 			},
 		},
 	}
@@ -124,8 +128,10 @@ func TestSendMetricsCantReachServer(t *testing.T) {
 			Host:       nil,
 			Tags:       []string{"a", "b", "c"},
 			MetricType: DistributionType,
-			Points: [][]float64{
-				{float64(1), float64(2)}, {float64(3), float64(4)}, {float64(5), float64(6)},
+			Points: []interface{}{
+				[]interface{}{float64(1), []interface{}{float64(2)}},
+				[]interface{}{float64(3), []interface{}{float64(4)}},
+				[]interface{}{float64(5), []interface{}{float64(6)}},
 			},
 		},
 	}

internal/metrics/batcher_test.go

@@ -138,8 +138,10 @@ func TestToAPIMetricsSameInterval(t *testing.T) {
 			Tags:       []string{"a", "b", "c"},
 			MetricType: DistributionType,
 			Interval:   nil,
-			Points: [][]float64{
-				{floatTime, 1}, {floatTime, 2}, {floatTime, 3},
+			Points: []interface{}{
+				[]interface{}{floatTime, []interface{}{float64(1)}},
+				[]interface{}{floatTime, []interface{}{float64(2)}},
+				[]interface{}{floatTime, []interface{}{float64(3)}},
 			},
 		},
 	}

internal/metrics/listener.go

@@ -38,7 +38,7 @@ func MakeListener(config Config) Listener {
 	if site == "" {
 		site = defaultSite
 	}
-	baseAPIURL := fmt.Sprintf("https://api.%s/api/v1/", config.Site)
+	baseAPIURL := fmt.Sprintf("https://api.%s/api/v1", site)
 
 	apiClient := MakeAPIClient(context.Background(), baseAPIURL, config.APIKey)
 	if config.BatchInterval <= 0 {

internal/metrics/model.go

@@ -23,12 +23,12 @@ type (
 
 	// APIMetric is a metric that can be marshalled to send to the metrics API
 	APIMetric struct {
-		Name       string      `json:"metric"`
-		Host       *string     `json:"host,omitempty"`
-		Tags       []string    `json:"tags,omitempty"`
-		MetricType MetricType  `json:"type"`
-		Interval   *float64    `json:"interval,omitempty"`
-		Points     [][]float64 `json:"points"`
+		Name       string        `json:"metric"`
+		Host       *string       `json:"host,omitempty"`
+		Tags       []string      `json:"tags,omitempty"`
+		MetricType MetricType    `json:"type"`
+		Interval   *float64      `json:"interval,omitempty"`
+		Points     []interface{} `json:"points"`
 	}
 
 	// MetricValue represents a datapoint for a metric
@@ -75,12 +75,12 @@ func (d *Distribution) Join(metric Metric) {
 
 // ToAPIMetric converts a distribution into an API ready format.
 func (d *Distribution) ToAPIMetric(interval time.Duration) []APIMetric {
-	points := make([][]float64, len(d.Values))
+	points := make([]interface{}, len(d.Values))
 
 	for i, val := range d.Values {
 		currentTime := float64(val.Timestamp.Unix())
 
-		points[i] = []float64{currentTime, val.Value}
+		points[i] = []interface{}{currentTime, []interface{}{val.Value}}
 	}
 
 	return []APIMetric{

internal/metrics/processor.go

@@ -10,9 +10,11 @@ package metrics
 
 import (
 	"context"
+	"fmt"
 	"sync"
 	"time"
 
+	"github.com/DataDog/datadog-lambda-go/internal/logger"
 	"github.com/cenkalti/backoff"
 )
 
@@ -110,9 +112,15 @@ func (p *processor) processMetrics() {
 			if shouldExit && p.shouldRetryOnFail {
 				// If we are shutting down, and we just failed to send our last batch, do a retry
 				bo := backoff.WithMaxRetries(backoff.NewConstantBackOff(defaultRetryInterval), 2)
-				backoff.Retry(p.sendMetricsBatch, bo)
+				err := backoff.Retry(p.sendMetricsBatch, bo)
+				if err != nil {
+					logger.Error(fmt.Errorf("failed to flush metrics to datadog API after retry: %v", err))
+				}
 			} else {
-				p.sendMetricsBatch()
+				err := p.sendMetricsBatch()
+				if err != nil {
+					logger.Error(fmt.Errorf("failed to flush metrics to datadog API: %v", err))
+				}
 			}
 		}
 	}