From 5f4cd838cfd4fc7825c0587d6b432808dc97b3f0 Mon Sep 17 00:00:00 2001 From: ffeldmann Date: Mon, 28 Feb 2022 09:45:57 +0100 Subject: [PATCH] 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 | 17 ++++++++++++----- pkg/telemetry/data.go | 8 +++----- pkg/telemetry/telemetry.go | 14 +++++++++----- pkg/telemetry/telemetry_test.go | 29 +++++++++++++++++++++-------- 4 files changed, 45 insertions(+), 23 deletions(-) diff --git a/pkg/splunk/splunk.go b/pkg/splunk/splunk.go index b9913a2f8..a0315f42b 100644 --- a/pkg/splunk/splunk.go +++ b/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 { diff --git a/pkg/telemetry/data.go b/pkg/telemetry/data.go index 2325cab0d..552aa21f2 100644 --- a/pkg/telemetry/data.go +++ b/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"` } diff --git a/pkg/telemetry/telemetry.go b/pkg/telemetry/telemetry.go index 158c7bea9..f726804b0 100644 --- a/pkg/telemetry/telemetry.go +++ b/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 { diff --git a/pkg/telemetry/telemetry_test.go b/pkg/telemetry/telemetry_test.go index 149d24c15..5cb8db3f2 100644 --- a/pkg/telemetry/telemetry_test.go +++ b/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() }) }