Logrus buffer issue

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

@@ -1,6 +1,7 @@
 package log
 
 import (
+	"io"
 	"strings"
 
 	"github.com/sirupsen/logrus"
@@ -35,13 +36,16 @@ var secrets []string
 func Entry() *logrus.Entry {
 	if logger == nil {
 		logger = logrus.WithField("library", LibraryRepository)
+		logger.Logger.SetFormatter(&RemoveSecretFormatterDecorator{})
 	}
-
-	logger.Logger.SetFormatter(&RemoveSecretFormatterDecorator{})
-
 	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()
+	}
+}