diff --git a/cmd/abapEnvironmentPullGitRepo.go b/cmd/abapEnvironmentPullGitRepo.go index a93cbcc518..aa750bd33a 100644 --- a/cmd/abapEnvironmentPullGitRepo.go +++ b/cmd/abapEnvironmentPullGitRepo.go @@ -178,7 +178,7 @@ func readCfServiceKey(config abapEnvironmentPullGitRepoOptions, c execRunner) (s var abapServiceKey serviceKey - c.Stderr(log.Entry().Writer()) + c.Stderr(log.Writer()) // Logging into the Cloud Foundry via CF CLI log.Entry().WithField("cfApiEndpoint", config.CfAPIEndpoint).WithField("cfSpace", config.CfSpace).WithField("cfOrg", config.CfOrg).WithField("User", config.Username).Info("Cloud Foundry parameters: ") diff --git a/cmd/artifactPrepareVersion.go b/cmd/artifactPrepareVersion.go index 3132b30f82..ac680644d2 100644 --- a/cmd/artifactPrepareVersion.go +++ b/cmd/artifactPrepareVersion.go @@ -45,8 +45,8 @@ func getGitWorktree(repository gitRepository) (gitWorktree, error) { func artifactPrepareVersion(config artifactPrepareVersionOptions, telemetryData *telemetry.CustomData, commonPipelineEnvironment *artifactPrepareVersionCommonPipelineEnvironment) { c := command.Command{} // reroute command output to logging framework - c.Stdout(log.Entry().Writer()) - c.Stderr(log.Entry().Writer()) + c.Stdout(log.Writer()) + c.Stderr(log.Writer()) // open local .git repository repository, err := openGit() diff --git a/cmd/cloudFoundryCreateServiceKey.go b/cmd/cloudFoundryCreateServiceKey.go index edb140ed83..8d38368ae5 100644 --- a/cmd/cloudFoundryCreateServiceKey.go +++ b/cmd/cloudFoundryCreateServiceKey.go @@ -12,8 +12,8 @@ func cloudFoundryCreateServiceKey(options cloudFoundryCreateServiceKeyOptions, t // for command execution use Command c := command.Command{} // reroute command output to logging framework - c.Stdout(log.Entry().Writer()) - c.Stderr(log.Entry().Writer()) + c.Stdout(log.Writer()) + c.Stderr(log.Writer()) config := cloudFoundryDeleteServiceOptions{ CfAPIEndpoint: options.CfAPIEndpoint, diff --git a/cmd/cloudFoundryDeleteService.go b/cmd/cloudFoundryDeleteService.go index 3b767fb29c..571411b5bb 100644 --- a/cmd/cloudFoundryDeleteService.go +++ b/cmd/cloudFoundryDeleteService.go @@ -15,8 +15,8 @@ func cloudFoundryDeleteService(options cloudFoundryDeleteServiceOptions, telemet c := command.Command{} // reroute command output to logging framework - c.Stdout(log.Entry().Writer()) - c.Stderr(log.Entry().Writer()) + c.Stdout(log.Writer()) + c.Stderr(log.Writer()) var err error diff --git a/cmd/detectExecuteScan.go b/cmd/detectExecuteScan.go index 876ce8b7c4..72d1267005 100644 --- a/cmd/detectExecuteScan.go +++ b/cmd/detectExecuteScan.go @@ -13,8 +13,8 @@ import ( func detectExecuteScan(config detectExecuteScanOptions, telemetryData *telemetry.CustomData) { c := command.Command{} // reroute command output to logging framework - c.Stdout(log.Entry().Writer()) - c.Stderr(log.Entry().Writer()) + c.Stdout(log.Writer()) + c.Stderr(log.Writer()) runDetect(config, &c) } diff --git a/cmd/gctsCreateRepository.go b/cmd/gctsCreateRepository.go index f18293e3e6..bfba9499cd 100644 --- a/cmd/gctsCreateRepository.go +++ b/cmd/gctsCreateRepository.go @@ -19,8 +19,8 @@ func gctsCreateRepository(config gctsCreateRepositoryOptions, telemetryData *tel // for command execution use Command c := command.Command{} // reroute command output to logging framework - c.Stdout(log.Entry().Writer()) - c.Stderr(log.Entry().Writer()) + c.Stdout(log.Writer()) + c.Stderr(log.Writer()) // for http calls import piperhttp "github.com/SAP/jenkins-library/pkg/http" // and use a &piperhttp.Client{} in a custom system diff --git a/cmd/karmaExecuteTests.go b/cmd/karmaExecuteTests.go index dd3c027875..d3b88763d9 100644 --- a/cmd/karmaExecuteTests.go +++ b/cmd/karmaExecuteTests.go @@ -12,8 +12,8 @@ func karmaExecuteTests(config karmaExecuteTestsOptions, telemetryData *telemetry c := command.Command{} // reroute command output to loging framework // also log stdout as Karma reports into it - c.Stdout(log.Entry().Writer()) - c.Stderr(log.Entry().Writer()) + c.Stdout(log.Writer()) + c.Stderr(log.Writer()) runKarma(config, &c) } diff --git a/cmd/kubernetesDeploy.go b/cmd/kubernetesDeploy.go index 1020d1ecba..77bfbf1f4d 100644 --- a/cmd/kubernetesDeploy.go +++ b/cmd/kubernetesDeploy.go @@ -18,8 +18,8 @@ import ( func kubernetesDeploy(config kubernetesDeployOptions, telemetryData *telemetry.CustomData) { c := command.Command{} // reroute stderr output to logging framework, stdout will be used for command interactions - c.Stderr(log.Entry().Writer()) - runKubernetesDeploy(config, &c, log.Entry().Writer()) + c.Stderr(log.Writer()) + runKubernetesDeploy(config, &c, log.Writer()) } func runKubernetesDeploy(config kubernetesDeployOptions, command execRunner, stdout io.Writer) { diff --git a/cmd/malwareExecuteScan.go b/cmd/malwareExecuteScan.go index abe3cdd7f5..2b0864eeab 100644 --- a/cmd/malwareExecuteScan.go +++ b/cmd/malwareExecuteScan.go @@ -34,8 +34,8 @@ func malwareExecuteScan(config malwareExecuteScanOptions, telemetryData *telemet // for command execution use Command c := command.Command{} // reroute command output to logging framework - c.Stdout(log.Entry().Writer()) - c.Stderr(log.Entry().Writer()) + c.Stdout(log.Writer()) + c.Stderr(log.Writer()) // for http calls import piperhttp "github.com/SAP/jenkins-library/pkg/http" // and use a &piperhttp.Client{} in a custom system diff --git a/cmd/mavenBuild.go b/cmd/mavenBuild.go index e16c9741ae..5a6b3ff2b9 100644 --- a/cmd/mavenBuild.go +++ b/cmd/mavenBuild.go @@ -11,8 +11,8 @@ import ( func mavenBuild(config mavenBuildOptions, telemetryData *telemetry.CustomData) { c := command.Command{} - c.Stdout(log.Entry().Writer()) - c.Stderr(log.Entry().Writer()) + c.Stdout(log.Writer()) + c.Stderr(log.Writer()) utils := piperutils.Files{} diff --git a/cmd/mavenExecuteStaticCodeChecks.go b/cmd/mavenExecuteStaticCodeChecks.go index 4a0de7b72a..9d2ce4eb1b 100644 --- a/cmd/mavenExecuteStaticCodeChecks.go +++ b/cmd/mavenExecuteStaticCodeChecks.go @@ -10,8 +10,8 @@ import ( func mavenExecuteStaticCodeChecks(config mavenExecuteStaticCodeChecksOptions, telemetryData *telemetry.CustomData) { c := command.Command{} - c.Stdout(log.Entry().Writer()) - c.Stderr(log.Entry().Writer()) + c.Stdout(log.Writer()) + c.Stderr(log.Writer()) err := runMavenStaticCodeChecks(&config, telemetryData, &c) if err != nil { log.Entry().WithError(err).Fatal("step execution failed") diff --git a/cmd/mtaBuild.go b/cmd/mtaBuild.go index c3f62ebcc6..04fe5c216b 100644 --- a/cmd/mtaBuild.go +++ b/cmd/mtaBuild.go @@ -95,8 +95,8 @@ func runMtaBuild(config mtaBuildOptions, p piperutils.FileUtils, httpClient piperhttp.Downloader) error { - e.Stdout(log.Entry().Writer()) // not sure if using the logging framework here is a suitable approach. We handover already log formatted - e.Stderr(log.Entry().Writer()) // entries to a logging framwork again. But this is considered to be some kind of project standard. + e.Stdout(log.Writer()) // not sure if using the logging framework here is a suitable approach. We handover already log formatted + e.Stderr(log.Writer()) // entries to a logging framework again. But this is considered to be some kind of project standard. var err error diff --git a/cmd/nexusUpload.go b/cmd/nexusUpload.go index 6778c5e455..ffedc33ee4 100644 --- a/cmd/nexusUpload.go +++ b/cmd/nexusUpload.go @@ -108,8 +108,8 @@ func (u *utilsBundle) getEnvParameter(path, name string) string { func (u *utilsBundle) getExecRunner() execRunner { if u.execRunner == nil { u.execRunner = &command.Command{} - u.execRunner.Stdout(log.Entry().Writer()) - u.execRunner.Stderr(log.Entry().Writer()) + u.execRunner.Stdout(log.Writer()) + u.execRunner.Stderr(log.Writer()) } return u.execRunner } diff --git a/cmd/npmExecuteScripts.go b/cmd/npmExecuteScripts.go index 48bed80c6c..bf5e728213 100644 --- a/cmd/npmExecuteScripts.go +++ b/cmd/npmExecuteScripts.go @@ -45,8 +45,8 @@ func (u *npmExecuteScriptsUtilsBundle) chdir(dir string) error { func (u *npmExecuteScriptsUtilsBundle) getExecRunner() execRunner { if u.execRunner == nil { u.execRunner = &command.Command{} - u.execRunner.Stdout(log.Entry().Writer()) - u.execRunner.Stderr(log.Entry().Writer()) + u.execRunner.Stdout(log.Writer()) + u.execRunner.Stderr(log.Writer()) } return u.execRunner } @@ -120,7 +120,7 @@ func setNpmRegistries(options *npmExecuteScriptsOptions, execRunner execRunner) var buffer bytes.Buffer execRunner.Stdout(&buffer) err := execRunner.RunExecutable("npm", "config", "get", registry) - execRunner.Stdout(log.Entry().Writer()) + execRunner.Stdout(log.Writer()) if err != nil { return err } diff --git a/cmd/protecodeExecuteScan.go b/cmd/protecodeExecuteScan.go index 88339ca33c..69539d79f4 100644 --- a/cmd/protecodeExecuteScan.go +++ b/cmd/protecodeExecuteScan.go @@ -42,8 +42,8 @@ var cacheProtecodePath = "/protecode" func protecodeExecuteScan(config protecodeExecuteScanOptions, telemetryData *telemetry.CustomData, influx *protecodeExecuteScanInflux) error { c := command.Command{} // reroute command output to loging framework - c.Stdout(log.Entry().Writer()) - c.Stderr(log.Entry().Writer()) + c.Stdout(log.Writer()) + c.Stderr(log.Writer()) dClient := createDockerClient(&config) return runProtecodeScan(&config, influx, dClient) diff --git a/cmd/sonarExecuteScan.go b/cmd/sonarExecuteScan.go index 2cef1fb83f..ef80863597 100644 --- a/cmd/sonarExecuteScan.go +++ b/cmd/sonarExecuteScan.go @@ -44,8 +44,8 @@ var osRename = os.Rename func sonarExecuteScan(config sonarExecuteScanOptions, _ *telemetry.CustomData) { runner := command.Command{} // reroute command output to logging framework - runner.Stdout(log.Entry().Writer()) - runner.Stderr(log.Entry().Writer()) + runner.Stdout(log.Writer()) + runner.Stderr(log.Writer()) client := piperhttp.Client{} client.SetOptions(piperhttp.ClientOptions{TransportTimeout: 20 * time.Second}) diff --git a/pkg/generator/helper/helper.go b/pkg/generator/helper/helper.go index 32466d5ce3..65ab2c0504 100644 --- a/pkg/generator/helper/helper.go +++ b/pkg/generator/helper/helper.go @@ -187,8 +187,8 @@ func {{.StepName}}(config {{ .StepName }}Options, telemetryData *telemetry.Custo // for command execution use Command c := command.Command{} // reroute command output to logging framework - c.Stdout(log.Entry().Writer()) - c.Stderr(log.Entry().Writer()) + c.Stdout(log.Writer()) + c.Stderr(log.Writer()) // for http calls import piperhttp "github.com/SAP/jenkins-library/pkg/http" // and use a &piperhttp.Client{} in a custom system diff --git a/pkg/log/log.go b/pkg/log/log.go index 4d385292d3..74254dbe4c 100644 --- a/pkg/log/log.go +++ b/pkg/log/log.go @@ -2,6 +2,7 @@ package log import ( "fmt" + "io" "strings" "github.com/sirupsen/logrus" @@ -60,6 +61,11 @@ func Entry() *logrus.Entry { return logger } +// Writer returns an io.Writer into which a tool's output can be redirected. +func Writer() io.Writer { + return &logrusWriter{logger: Entry()} +} + // SetVerbose sets the log level with respect to verbose flag. func SetVerbose(verbose bool) { if verbose { diff --git a/pkg/log/log_test.go b/pkg/log/log_test.go index 434e12ec0b..3379aead61 100644 --- a/pkg/log/log_test.go +++ b/pkg/log/log_test.go @@ -10,8 +10,11 @@ func TestSecrets(t *testing.T) { t.Run("should log", func(t *testing.T) { secret := "password" + outWriter := Entry().Logger.Out var buffer bytes.Buffer Entry().Logger.SetOutput(&buffer) + defer func() { Entry().Logger.SetOutput(outWriter) }() + Entry().Infof("My secret is %s.", secret) assert.Contains(t, buffer.String(), secret) @@ -21,3 +24,24 @@ func TestSecrets(t *testing.T) { assert.NotContains(t, buffer.String(), secret) }) } + +func TestWriteLargeBuffer(t *testing.T) { + t.Run("should log large buffer without linebreaks via Writer()", func(t *testing.T) { + b := []byte("a") + size := 131072 + b = bytes.Repeat(b, size) + written, err := Writer().Write(b) + assert.Equal(t, size, written) + assert.NoError(t, err) + }) + t.Run("fails writing large buffer without linebreaks via Entry().Writer()", func(t *testing.T) { + // NOTE: If this test starts failing, then the logrus issue has been fixed and + // the work-around with Writer() can be removed. + b := []byte("a") + size := 131072 + b = bytes.Repeat(b, size) + written, err := Entry().Writer().Write(b) + assert.Error(t, err) + assert.True(t, size != written) + }) +} diff --git a/pkg/log/writer.go b/pkg/log/writer.go new file mode 100644 index 0000000000..2dea3752c9 --- /dev/null +++ b/pkg/log/writer.go @@ -0,0 +1,68 @@ +package log + +import ( + "bytes" + "strings" + "sync" +) + +type logTarget interface { + Info(args ...interface{}) + Warn(args ...interface{}) + Error(args ...interface{}) +} + +// logrusWriter can be used as the destination for a tool's std output and forwards +// chunks between linebreaks to the logrus framework. This works around a problem +// with using Entry().Writer() directly, since that doesn't support chunks +// larger than 64K without linebreaks. +// Implementation copied from https://github.com/sirupsen/logrus/issues/564 +type logrusWriter struct { + logger logTarget + buffer bytes.Buffer + mutex sync.Mutex +} + +func (w *logrusWriter) Write(buffer []byte) (int, error) { + w.mutex.Lock() + defer w.mutex.Unlock() + + origLen := len(buffer) + for { + if len(buffer) == 0 { + return origLen, nil + } + linebreakIndex := bytes.IndexByte(buffer, '\n') + if linebreakIndex < 0 { + w.buffer.Write(buffer) + return origLen, nil + } + + w.buffer.Write(buffer[:linebreakIndex]) + w.alwaysFlush() + buffer = buffer[linebreakIndex+1:] + } +} + +func (w *logrusWriter) alwaysFlush() { + message := w.buffer.String() + w.buffer.Reset() + // Align level with underlying tool (like maven or npm) + // This is to avoid confusion when maven or npm print errors or warnings which piper would print as "info" + if strings.Contains(message, "ERROR") || strings.Contains(message, "ERR!") { + w.logger.Error(message) + } else if strings.Contains(message, "WARN") { + w.logger.Warn(message) + } else { + w.logger.Info(message) + } +} + +func (w *logrusWriter) Flush() { + w.mutex.Lock() + defer w.mutex.Unlock() + + if w.buffer.Len() != 0 { + w.alwaysFlush() + } +} diff --git a/pkg/log/writer_test.go b/pkg/log/writer_test.go new file mode 100644 index 0000000000..1109b2ce6c --- /dev/null +++ b/pkg/log/writer_test.go @@ -0,0 +1,150 @@ +package log + +import ( + "fmt" + "github.com/stretchr/testify/assert" + "testing" +) + +type mockLogger struct { + infoLines []string + warnLines []string + errorLines []string +} + +func newMockLogger() *mockLogger { + var logger = mockLogger{} + return &logger +} + +func (l *mockLogger) Info(args ...interface{}) { + l.infoLines = append(l.infoLines, fmt.Sprint(args...)) +} + +func (l *mockLogger) Warn(args ...interface{}) { + l.warnLines = append(l.warnLines, fmt.Sprint(args...)) +} + +func (l *mockLogger) Error(args ...interface{}) { + l.errorLines = append(l.errorLines, fmt.Sprint(args...)) +} + +func TestWriter(t *testing.T) { + t.Run("should buffer and append correctly", func(t *testing.T) { + mockLogger := newMockLogger() + writer := logrusWriter{logger: mockLogger} + + written, err := writer.Write([]byte("line ")) + assert.Equal(t, len("line "), written) + assert.NoError(t, err) + + written, err = writer.Write([]byte("without ")) + assert.Equal(t, len("without "), written) + assert.NoError(t, err) + + written, err = writer.Write([]byte("linebreaks")) + assert.Equal(t, len("linebreaks"), written) + assert.NoError(t, err) + + assert.Equal(t, 0, len(mockLogger.infoLines)) + assert.Equal(t, 0, len(mockLogger.warnLines)) + assert.Equal(t, 0, len(mockLogger.errorLines)) + + assert.Equal(t, "line without linebreaks", writer.buffer.String()) + }) + + t.Run("should forward to info log", func(t *testing.T) { + mockLogger := newMockLogger() + writer := logrusWriter{logger: mockLogger} + + line := "line with linebreak\n" + + written, err := writer.Write([]byte(line)) + assert.Equal(t, len(line), written) + assert.NoError(t, err) + + if assert.Equal(t, 1, len(mockLogger.infoLines)) { + assert.Equal(t, "line with linebreak", mockLogger.infoLines[0]) + } + assert.Equal(t, 0, len(mockLogger.warnLines)) + assert.Equal(t, 0, len(mockLogger.errorLines)) + + assert.Equal(t, 0, writer.buffer.Len()) + }) + t.Run("should split at line breaks", func(t *testing.T) { + mockLogger := newMockLogger() + writer := logrusWriter{logger: mockLogger} + + input := "line\nwith\nlinebreaks\n" + + written, err := writer.Write([]byte(input)) + assert.Equal(t, len(input), written) + assert.NoError(t, err) + + if assert.Equal(t, 3, len(mockLogger.infoLines)) { + assert.Equal(t, "line", mockLogger.infoLines[0]) + assert.Equal(t, "with", mockLogger.infoLines[1]) + assert.Equal(t, "linebreaks", mockLogger.infoLines[2]) + } + assert.Equal(t, 0, len(mockLogger.warnLines)) + assert.Equal(t, 0, len(mockLogger.errorLines)) + + assert.Equal(t, 0, writer.buffer.Len()) + }) + t.Run("should output empty lines", func(t *testing.T) { + mockLogger := newMockLogger() + writer := logrusWriter{logger: mockLogger} + + input := "\n\n" + + written, err := writer.Write([]byte(input)) + assert.Equal(t, len(input), written) + assert.NoError(t, err) + + if assert.Equal(t, 2, len(mockLogger.infoLines)) { + assert.Equal(t, "", mockLogger.infoLines[0]) + assert.Equal(t, "", mockLogger.infoLines[1]) + } + assert.Equal(t, 0, len(mockLogger.warnLines)) + assert.Equal(t, 0, len(mockLogger.errorLines)) + + assert.Equal(t, 0, writer.buffer.Len()) + }) + t.Run("should ignore empty input", func(t *testing.T) { + mockLogger := newMockLogger() + writer := logrusWriter{logger: mockLogger} + + written, err := writer.Write([]byte("")) + assert.Equal(t, 0, written) + assert.NoError(t, err) + + assert.Equal(t, 0, len(mockLogger.infoLines)) + assert.Equal(t, 0, len(mockLogger.warnLines)) + assert.Equal(t, 0, len(mockLogger.errorLines)) + + assert.Equal(t, 0, writer.buffer.Len()) + }) + t.Run("should align log level", func(t *testing.T) { + mockLogger := newMockLogger() + writer := logrusWriter{logger: mockLogger} + + input := "I will count to three.\n1\nWARNING: 2\nERROR: 3\n" + + written, err := writer.Write([]byte(input)) + assert.Equal(t, len(input), written) + assert.NoError(t, err) + + if assert.Equal(t, 2, len(mockLogger.infoLines)) { + assert.Equal(t, "I will count to three.", mockLogger.infoLines[0]) + assert.Equal(t, "1", mockLogger.infoLines[1]) + } + if assert.Equal(t, 1, len(mockLogger.warnLines)) { + assert.Equal(t, "WARNING: 2", mockLogger.warnLines[0]) + } + if assert.Equal(t, 1, len(mockLogger.errorLines)) { + assert.Equal(t, "ERROR: 3", mockLogger.errorLines[0]) + } + + assert.Equal(t, 0, writer.buffer.Len()) + }) +} diff --git a/pkg/maven/maven.go b/pkg/maven/maven.go index 7ea79f4deb..0f4b43173d 100644 --- a/pkg/maven/maven.go +++ b/pkg/maven/maven.go @@ -63,7 +63,7 @@ const mavenExecutable = "mvn" func Execute(options *ExecuteOptions, command mavenExecRunner) (string, error) { stdOutBuf, stdOut := evaluateStdOut(options) command.Stdout(stdOut) - command.Stderr(log.Entry().Writer()) + command.Stderr(log.Writer()) parameters, err := getParametersFromOptions(options, newUtils()) if err != nil { @@ -105,9 +105,7 @@ func Evaluate(pomFile, expression string, command mavenExecRunner) (string, erro func evaluateStdOut(config *ExecuteOptions) (*bytes.Buffer, io.Writer) { var stdOutBuf *bytes.Buffer - var stdOut io.Writer - - stdOut = log.Entry().Writer() + stdOut := log.Writer() if config.ReturnStdout { stdOutBuf = new(bytes.Buffer) stdOut = io.MultiWriter(stdOut, stdOutBuf)