Fix logrus buffer issue (#1511)

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: ")

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()

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,

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
 

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)
 }
 

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

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)
 }
 

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) {

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

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{}
 

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")

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
 

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
 }

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
 		}

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)

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})

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

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 {

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)
+	})
+}

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()
+	}
+}

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())
+	})
+}

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)