Merge branch 'jc-add-stderr-to-err' into 'master'

Log stderr returned by the command

Closes #1491

See merge request gitlab-org/gitaly!1167

7 files changed, 176 insertions, 10 deletions

diff --git a/changelogs/unreleased/jc-add-stderr-to-err.yml b/changelogs/unreleased/jc-add-stderr-to-err.yml
new file mode 100644
index 000000000..3418311c0
--- /dev/null
+++ b/changelogs/unreleased/jc-add-stderr-to-err.yml
@@ -0,0 +1,5 @@
+---
+title: Include stderr in err returned by git.Command Wait()
+merge_request: 1167
+author:
+type: fixed
diff --git a/internal/command/command.go b/internal/command/command.go
index 9272de8bf..c6f911ece 100644
--- a/internal/command/command.go
+++ b/internal/command/command.go
@@ -1,6 +1,7 @@
 package command
 
 import (
+	"bufio"
 	"context"
 	"errors"
 	"fmt"
@@ -14,10 +15,15 @@ import (
 	"time"
 
 	grpc_logrus "github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus"
+	"github.com/sirupsen/logrus"
 	log "github.com/sirupsen/logrus"
 	"gitlab.com/gitlab-org/gitaly/internal/config"
 )
 
+const (
+	escapedNewline = `\n`
+)
+
 // GitEnv contains the ENV variables for git commands
 var GitEnv = []string{
 	// Force english locale for consistency on the output messages
@@ -49,13 +55,22 @@ var exportedEnvVars = []string{
 	"no_proxy",
 }
 
+const (
+	// MaxStderrBytes is at most how many bytes will be written to stderr
+	MaxStderrBytes = 10000 // 10kb
+	// StderrBufferSize is the buffer size we use for the reader that reads from
+	// the stderr stream of the command
+	StderrBufferSize = 4096
+)
+
 // Command encapsulates a running exec.Cmd. The embedded exec.Cmd is
 // terminated and reaped automatically when the context.Context that
 // created it is canceled.
 type Command struct {
 	reader       io.Reader
 	writer       io.WriteCloser
-	logrusWriter io.WriteCloser
+	stderrCloser io.WriteCloser
+	stderrDone   chan struct{}
 	cmd          *exec.Cmd
 	context      context.Context
 	startTime    time.Time
@@ -163,9 +178,10 @@ func New(ctx context.Context, cmd *exec.Cmd, stdin io.Reader, stdout, stderr io.
 	}()
 
 	command := &Command{
-		cmd:       cmd,
-		startTime: time.Now(),
-		context:   ctx,
+		cmd:        cmd,
+		startTime:  time.Now(),
+		context:    ctx,
+		stderrDone: make(chan struct{}),
 	}
 
 	// Explicitly set the environment for the command
@@ -204,13 +220,13 @@ func New(ctx context.Context, cmd *exec.Cmd, stdin io.Reader, stdout, stderr io.
 	}
 
 	if stderr != nil {
-		cmd.Stderr = stderr
+		command.stderrCloser = escapeNewlineWriter(stderr, command.stderrDone, MaxStderrBytes)
 	} else {
-		// If we don't do something with cmd.Stderr, Git errors will be lost
-		command.logrusWriter = grpc_logrus.Extract(ctx).WriterLevel(log.InfoLevel)
-		cmd.Stderr = command.logrusWriter
+		command.stderrCloser = escapeNewlineWriter(grpc_logrus.Extract(ctx).WriterLevel(log.ErrorLevel), command.stderrDone, MaxStderrBytes)
 	}
 
+	cmd.Stderr = command.stderrCloser
+
 	if err := cmd.Start(); err != nil {
 		return nil, fmt.Errorf("GitCommand: start %v: %v", cmd.Args, err)
 	}
@@ -244,6 +260,70 @@ func exportEnvironment(env []string) []string {
 	return env
 }
 
+func escapeNewlineWriter(outbound io.Writer, done chan struct{}, maxBytes int) io.WriteCloser {
+	r, w := io.Pipe()
+
+	go writeLines(outbound, r, done, maxBytes)
+
+	return w
+}
+
+func writeLines(writer io.Writer, reader io.Reader, done chan struct{}, maxBytes int) {
+	var bytesWritten int
+
+	bufReader := bufio.NewReaderSize(reader, StderrBufferSize)
+
+	var err error
+	var b []byte
+	var isPrefix, discardRestOfLine bool
+
+	for err == nil {
+		b, isPrefix, err = bufReader.ReadLine()
+
+		if discardRestOfLine {
+			ioutil.Discard.Write(b)
+			// if isPrefix = false, that means the reader has gotten to the end
+			// of the line. We want to read the first chunk of the  next line
+			if !isPrefix {
+				discardRestOfLine = false
+			}
+			continue
+		}
+
+		// if we've reached the max, discard
+		if bytesWritten >= maxBytes {
+			ioutil.Discard.Write(b)
+			continue
+		}
+
+		// only write up to the max
+		if len(b)+bytesWritten+len(escapedNewline) >= maxBytes {
+			b = b[:maxBytes-bytesWritten-len(escapedNewline)]
+		}
+
+		// prepend an escaped newline
+		if bytesWritten > 0 {
+			b = append([]byte(escapedNewline), b...)
+		}
+
+		n, _ := writer.Write(b)
+		bytesWritten += n
+
+		// if isPrefix, it means the line is too long so we want to discard the rest
+		if isPrefix {
+			discardRestOfLine = true
+		}
+	}
+
+	// read the rest so the command doesn't get blocked
+	if err != io.EOF {
+		logrus.WithError(err).Error("error while reading from Writer")
+		io.Copy(ioutil.Discard, reader)
+	}
+
+	done <- struct{}{}
+}
+
 // This function should never be called directly, use Wait().
 func (c *Command) wait() {
 	if c.writer != nil {
@@ -267,10 +347,11 @@ func (c *Command) wait() {
 
 	c.logProcessComplete(c.context, exitCode)
 
-	if w := c.logrusWriter; w != nil {
-		// Closing this writer lets a logrus goroutine finish early
+	if w := c.stderrCloser; w != nil {
 		w.Close()
 	}
+
+	<-c.stderrDone
 }
 
 // ExitStatus will return the exit-code from an error returned by Wait().
diff --git a/internal/command/command_test.go b/internal/command/command_test.go
index feaf52711..151a4a35f 100644
--- a/internal/command/command_test.go
+++ b/internal/command/command_test.go
@@ -11,6 +11,7 @@ import (
 	"testing"
 	"time"
 
+	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 )
 
@@ -187,3 +188,61 @@ func TestNewCommandNullInArg(t *testing.T) {
 	_, ok := err.(nullInArgvError)
 	require.True(t, ok, "expected %+v to be nullInArgvError", err)
 }
+
+func TestCommandStdErr(t *testing.T) {
+	ctx, cancel := context.WithCancel(context.Background())
+	defer cancel()
+
+	var stdout, stderr bytes.Buffer
+
+	cmd, err := New(ctx, exec.Command("./testdata/stderr_script.sh"), nil, &stdout, &stderr)
+	require.NoError(t, err)
+
+	require.Error(t, cmd.Wait())
+	assert.Empty(t, stdout.Bytes())
+	assert.Equal(t, `hello world\nhello world\nhello world\nhello world\nhello world\n`, stderr.String())
+}
+
+func TestCommandStdErrLargeOutput(t *testing.T) {
+	ctx, cancel := context.WithCancel(context.Background())
+	defer cancel()
+
+	var stdout, stderr bytes.Buffer
+
+	cmd, err := New(ctx, exec.Command("./testdata/stderr_many_lines.sh"), nil, &stdout, &stderr)
+	require.NoError(t, err)
+
+	require.Error(t, cmd.Wait())
+	assert.Empty(t, stdout.Bytes())
+	assert.True(t, stderr.Len() <= MaxStderrBytes)
+}
+
+func TestCommandStdErrBinaryNullBytes(t *testing.T) {
+	ctx, cancel := context.WithCancel(context.Background())
+	defer cancel()
+
+	var stdout, stderr bytes.Buffer
+
+	cmd, err := New(ctx, exec.Command("./testdata/stderr_binary_null.sh"), nil, &stdout, &stderr)
+	require.NoError(t, err)
+
+	require.Error(t, cmd.Wait())
+	assert.Empty(t, stdout.Bytes())
+	assert.NotEmpty(t, stderr.Bytes())
+}
+
+func TestCommandStdErrLongLine(t *testing.T) {
+	ctx, cancel := context.WithCancel(context.Background())
+	defer cancel()
+
+	var stdout, stderr bytes.Buffer
+
+	cmd, err := New(ctx, exec.Command("./testdata/stderr_repeat_a.sh"), nil, &stdout, &stderr)
+	require.NoError(t, err)
+
+	require.Error(t, cmd.Wait())
+	assert.Empty(t, stdout.Bytes())
+	assert.NotEmpty(t, stderr.Bytes())
+	assert.Equal(t, fmt.Sprintf("%s\\n%s", strings.Repeat("a", StderrBufferSize), strings.Repeat("b", StderrBufferSize)), stderr.String())
+	//	t.Logf(stderr.String())
+}
diff --git a/internal/command/testdata/stderr_binary_null.sh b/internal/command/testdata/stderr_binary_null.sh
new file mode 100755
index 000000000..8b7a7f6e7
--- /dev/null
+++ b/internal/command/testdata/stderr_binary_null.sh
@@ -0,0 +1,4 @@
+#!/bin/bash
+
+dd if=/dev/zero bs=1000 count=1000 >&2;
+exit 1;
\ No newline at end of file
diff --git a/internal/command/testdata/stderr_many_lines.sh b/internal/command/testdata/stderr_many_lines.sh
new file mode 100755
index 000000000..7a346328f
--- /dev/null
+++ b/internal/command/testdata/stderr_many_lines.sh
@@ -0,0 +1,4 @@
+#!/bin/bash
+
+let x=0; while [ $x -lt 100010 ]; do let x=x+1; printf '%06d zzzzzzzzzz\n' $x >&2 ; done
+exit 1;
\ No newline at end of file
diff --git a/internal/command/testdata/stderr_repeat_a.sh b/internal/command/testdata/stderr_repeat_a.sh
new file mode 100755
index 000000000..0c967e730
--- /dev/null
+++ b/internal/command/testdata/stderr_repeat_a.sh
@@ -0,0 +1,6 @@
+#!/bin/bash
+
+printf 'a%.0s' {1..8192} >&2
+printf '\n' >&2
+printf 'b%.0s' {1..8192} >&2
+exit 1;
\ No newline at end of file
diff --git a/internal/command/testdata/stderr_script.sh b/internal/command/testdata/stderr_script.sh
new file mode 100755
index 000000000..807d9860e
--- /dev/null
+++ b/internal/command/testdata/stderr_script.sh
@@ -0,0 +1,7 @@
+#!/bin/bash
+
+for i in {1..5}
+do
+    echo 'hello world' 1>&2
+done
+exit 1
\ No newline at end of file