Updates telemetry logging information for internal reporting (#3585)

* Add StepStartTime, Renames StepDuration, adds PiperCommithash, removes Branch, GitOwner, GitRepository from logged telemetry information

* Fixes test case for telemetry logging

* Activates step monitoring data in debug mode

* Pretty debug json printing

* Reduces log noise, setting warning to debug

pkg/splunk/splunk.go

@@ -31,7 +31,7 @@ type Splunk struct {
 	// boolean which forces to send all logs on error or none at all
 	sendLogs bool
 
-	// How big can be batch of messages
+	// How large a batch of messages can be
 	postMessagesBatchSize int
 }
 
@@ -96,7 +96,7 @@ func readCommonPipelineEnvironment(filePath string) string {
 	// TODO: Dependent on a groovy step, which creates the folder.
 	contentFile, err := ioutil.ReadFile(".pipeline/commonPipelineEnvironment/" + filePath)
 	if err != nil {
-		log.Entry().Warnf("Could not read %v file. %v", filePath, err)
+		log.Entry().Debugf("Could not read %v file. %v", filePath, err)
 		contentFile = []byte("N/A")
 	}
 	return string(contentFile)
@@ -122,10 +122,10 @@ func (s *Splunk) prepareTelemetry(telemetryData telemetry.Data) MonitoringData {
 	monitoringJson, err := json.Marshal(monitoringData)
 	if err != nil {
 		log.Entry().Error("could not marshal monitoring data")
-		log.Entry().Infof("Step monitoring data: {n/a}")
+		log.Entry().Debugf("Step monitoring data: {n/a}")
 	} else {
 		// log step monitoring data, changes here need to change the regex in the internal piper lib
-		log.Entry().Infof("Step monitoring data:%v", string(monitoringJson))
+		log.Entry().Debugf("Step monitoring data:%v", string(monitoringJson))
 	}
 
 	return monitoringData
@@ -172,7 +172,14 @@ func (s *Splunk) postTelemetry(telemetryData map[string]interface{}) error {
 	if err != nil {
 		return errors.Wrap(err, "error while marshalling Splunk message details")
 	}
-	log.Entry().Debugf("Sending the follwing payload to Splunk HEC: %v", string(payload))
+
+	prettyPayload, err := json.MarshalIndent(payload, "", "    ")
+	if err != nil {
+		log.Entry().WithError(err).Warn("Failed to generate pretty payload json")
+		prettyPayload = nil
+	}
+	log.Entry().Debugf("Sending the follwing payload to Splunk HEC: %s", string(prettyPayload))
+
 	resp, err := s.splunkClient.SendRequest(http.MethodPost, s.splunkDsn, bytes.NewBuffer(payload), nil, nil)
 
 	if resp != nil {

pkg/telemetry/data.go

@@ -71,18 +71,16 @@ type CustomData struct {
 
 // StepTelemetryData definition for telemetry reporting and monitoring
 type StepTelemetryData struct {
+	StepStartTime   string                 `json:"StepStartTime"`
 	PipelineURLHash string                 `json:"PipelineURLHash"`
 	BuildURLHash    string                 `json:"BuildURLHash"`
 	StageName       string                 `json:"StageName"`
 	StepName        string                 `json:"StepName"`
 	ErrorCode       string                 `json:"ErrorCode"`
-	Duration        string                 `json:"Duration"`
+	StepDuration    string                 `json:"StepDuration"`
 	ErrorCategory   string                 `json:"ErrorCategory"`
 	CorrelationID   string                 `json:"CorrelationID"`
-	CommitHash      string                 `json:"CommitHash"`
-	Branch          string                 `json:"Branch"`
-	GitOwner        string                 `json:"GitOwner"`
-	GitRepository   string                 `json:"GitRepository"`
+	PiperCommitHash string                 `json:"PiperCommitHash"`
 	ErrorDetail     map[string]interface{} `json:"ErrorDetail"`
 }
 

pkg/telemetry/telemetry.go

@@ -5,6 +5,7 @@ import (
 	"encoding/json"
 	"fmt"
 	"github.com/SAP/jenkins-library/pkg/orchestrator"
+	"strconv"
 	"time"
 
 	"net/http"
@@ -145,20 +146,23 @@ func (t *Telemetry) logStepTelemetryData() {
 		}
 	}
 
+	// Subtracts the duration from now to estimate the step start time
+	i, err := strconv.ParseInt(t.data.CustomData.Duration, 10, 64)
+	duration := time.Millisecond * time.Duration(i)
+	starTime := time.Now().UTC().Add(-duration)
+
 	stepTelemetryData := StepTelemetryData{
+		StepStartTime:   starTime.String(),
 		PipelineURLHash: t.data.PipelineURLHash,
 		BuildURLHash:    t.data.BuildURLHash,
 		StageName:       t.data.StageName,
 		StepName:        t.data.BaseData.StepName,
 		ErrorCode:       t.data.CustomData.ErrorCode,
-		Duration:        t.data.CustomData.Duration,
+		StepDuration:    t.data.CustomData.Duration,
 		ErrorCategory:   t.data.CustomData.ErrorCategory,
 		ErrorDetail:     fatalError,
 		CorrelationID:   t.provider.GetBuildUrl(),
-		CommitHash:      t.provider.GetCommit(),
-		Branch:          t.provider.GetBranch(),
-		GitOwner:        t.provider.GetRepoUrl(), // TODO not correct
-		GitRepository:   t.provider.GetRepoUrl(), // TODO not correct
+		PiperCommitHash: t.data.CustomData.PiperCommitHash,
 	}
 	stepTelemetryJSON, err := json.Marshal(stepTelemetryData)
 	if err != nil {

pkg/telemetry/telemetry_test.go

@@ -10,6 +10,7 @@ import (
 	"github.com/sirupsen/logrus/hooks/test"
 	"net/http"
 	"reflect"
+	"regexp"
 	"testing"
 	"time"
 
@@ -270,7 +271,7 @@ func TestTelemetry_logStepTelemetryData(t *testing.T) {
 		name       string
 		fields     fields
 		fatalError logrus.Fields
-		logOutput  string // TODO
+		logOutput  string
 	}{
 		{
 			name: "logging with error, no fatalError set",
@@ -278,7 +279,11 @@ func TestTelemetry_logStepTelemetryData(t *testing.T) {
 				data: Data{
 					BaseData:     BaseData{},
 					BaseMetaData: BaseMetaData{},
-					CustomData:   CustomData{ErrorCode: "1"},
+					CustomData: CustomData{
+						ErrorCode:       "1",
+						Duration:        "200",
+						PiperCommitHash: "n/a",
+					},
 				},
 				provider: provider,
 			},
@@ -289,7 +294,11 @@ func TestTelemetry_logStepTelemetryData(t *testing.T) {
 				data: Data{
 					BaseData:     BaseData{},
 					BaseMetaData: BaseMetaData{},
-					CustomData:   CustomData{ErrorCode: "1"},
+					CustomData: CustomData{
+						ErrorCode:       "1",
+						Duration:        "200",
+						PiperCommitHash: "n/a",
+					},
 				},
 				provider: provider,
 			},
@@ -306,7 +315,11 @@ func TestTelemetry_logStepTelemetryData(t *testing.T) {
 			name: "logging without error",
 			fields: fields{
 				data: Data{
-					CustomData: CustomData{ErrorCode: "0"},
+					CustomData: CustomData{
+						ErrorCode:       "0",
+						Duration:        "200",
+						PiperCommitHash: "n/a",
+					},
 				},
 				provider: provider,
 			},
@@ -320,17 +333,17 @@ func TestTelemetry_logStepTelemetryData(t *testing.T) {
 				data:     tt.fields.data,
 				provider: tt.fields.provider,
 			}
-			var expected string
+			var re *regexp.Regexp
 			if tt.fatalError != nil {
 				errDetails, _ := json.Marshal(&tt.fatalError)
 				log.SetFatalErrorDetail(errDetails)
-				expected = "Step telemetry data:{\"PipelineURLHash\":\"\",\"BuildURLHash\":\"\",\"StageName\":\"\",\"StepName\":\"\",\"ErrorCode\":\"" + tt.fields.data.ErrorCode + "\",\"Duration\":\"\",\"ErrorCategory\":\"\",\"CorrelationID\":\"n/a\",\"CommitHash\":\"n/a\",\"Branch\":\"n/a\",\"GitOwner\":\"n/a\",\"GitRepository\":\"n/a\",\"ErrorDetail\":" + string(errDetails) + "}"
+				re = regexp.MustCompile(`Step telemetry data:{"StepStartTime":".*?","PipelineURLHash":"","BuildURLHash":"","StageName":"","StepName":"","ErrorCode":"\d","StepDuration":"\d+","ErrorCategory":"","CorrelationID":"n/a","PiperCommitHash":"n/a","ErrorDetail":{"category":"undefined","correlationId":"test","error":"Oh snap!","message":"Some error happened","result":"failure","time":"0000-00-00 00:00:00.000"}}`)
 
 			} else {
-				expected = "Step telemetry data:{\"PipelineURLHash\":\"\",\"BuildURLHash\":\"\",\"StageName\":\"\",\"StepName\":\"\",\"ErrorCode\":\"" + tt.fields.data.ErrorCode + "\",\"Duration\":\"\",\"ErrorCategory\":\"\",\"CorrelationID\":\"n/a\",\"CommitHash\":\"n/a\",\"Branch\":\"n/a\",\"GitOwner\":\"n/a\",\"GitRepository\":\"n/a\",\"ErrorDetail\":null}"
+				re = regexp.MustCompile(`Step telemetry data:{"StepStartTime":".*?","PipelineURLHash":"","BuildURLHash":"","StageName":"","StepName":"","ErrorCode":"\d","StepDuration":"\d+","ErrorCategory":"","CorrelationID":"n/a","PiperCommitHash":"n/a","ErrorDetail":null}`)
 			}
 			telemetry.logStepTelemetryData()
-			assert.Equal(t, expected, hook.LastEntry().Message)
+			assert.Regexp(t, re, hook.LastEntry().Message)
 			hook.Reset()
 		})
 	}