[ACI-4111] Add a log interceptor (#283)

* Add a log interceptor

Singles out [Bitrise ...] logs from the rest and forwards them to stdout

* Close intercepted writer

* Log writer and scanner errors to stderr

* Update loginterceptor/loginterceptor.go

Co-authored-by: bitrise-ip-bot <95076763+bitrise-ip-bot@users.noreply.github.com>

* Fix regex

Co-authored-by: bitrise-ip-bot <95076763+bitrise-ip-bot@users.noreply.github.com>

* Close pipe reader on coroutine end

Co-authored-by: bitrise-ip-bot <95076763+bitrise-ip-bot@users.noreply.github.com>

* Fix AI review suggestions

* Remove pr close on run, Close() handles it

* Add test for interceptor and close chained writers on interceptor close

* Make closing optional for interceptor writers

* Update variable names, introduce logger, update closing mechanism

* Close reader too, restructure after goroutine closing

* Remove superfuous writer close

---------

Co-authored-by: bitrise-ip-bot <95076763+bitrise-ip-bot@users.noreply.github.com>

Author: Badlazzor

loginterceptor/loginterceptor.go

@@ -0,0 +1,106 @@
+package loginterceptor
+
+import (
+	"bufio"
+	"io"
+	"regexp"
+	"sync"
+
+	"github.com/bitrise-io/go-utils/v2/log"
+)
+
+// PrefixInterceptor intercept writes: if a line begins with prefix, it will be written to
+// both writers. Partial writes without newline are buffered until a newline.
+type PrefixInterceptor struct {
+	prefixRegexp *regexp.Regexp
+	intercepted  io.Writer
+	target       io.Writer
+	logger       log.Logger
+
+	// internal pipe and goroutine to scan and route
+	internalReader *io.PipeReader
+	internalWriter *io.PipeWriter
+
+	// close once
+	closeOnce sync.Once
+	closeErr  error
+}
+
+// NewPrefixInterceptor returns an io.WriteCloser. Writes are based on line prefix.
+func NewPrefixInterceptor(prefixRegexp *regexp.Regexp, intercepted, target io.Writer, logger log.Logger) *PrefixInterceptor {
+	pipeReader, pipeWriter := io.Pipe()
+	interceptor := &PrefixInterceptor{
+		prefixRegexp:   prefixRegexp,
+		intercepted:    intercepted,
+		target:         target,
+		logger:         logger,
+		internalReader: pipeReader,
+		internalWriter: pipeWriter,
+	}
+	go interceptor.run()
+	return interceptor
+}
+
+// Write implements io.Writer. It writes into an internal pipe which the interceptor goroutine consumes.
+func (i *PrefixInterceptor) Write(p []byte) (int, error) {
+	return i.internalWriter.Write(p)
+}
+
+// Close stops the interceptor and closes the pipe.
+func (i *PrefixInterceptor) Close() error {
+	i.closeOnce.Do(func() {
+		i.closeErr = i.internalWriter.Close()
+	})
+	return i.closeErr
+}
+
+func (i *PrefixInterceptor) closeAfterRun() {
+	// Close writers if able
+	if interceptedCloser, ok := i.intercepted.(io.Closer); ok {
+		if err := interceptedCloser.Close(); err != nil {
+			i.logger.Errorf("closing intercepted writer: %v", err)
+		}
+	}
+	if originalCloser, ok := i.target.(io.Closer); ok {
+		if err := originalCloser.Close(); err != nil {
+			i.logger.Errorf("closing original writer: %v", err)
+		}
+	}
+
+	if err := i.internalReader.Close(); err != nil {
+		i.logger.Errorf("internal reader: %v", err)
+	}
+}
+
+// run reads lines (and partial final chunk) and writes them.
+func (i *PrefixInterceptor) run() {
+	defer i.closeAfterRun()
+
+	// Use a scanner but with a large buffer to handle long lines.
+	scanner := bufio.NewScanner(i.internalReader)
+	const maxTokenSize = 10 * 1024 * 1024
+	buf := make([]byte, 0, 64*1024)
+	scanner.Buffer(buf, maxTokenSize)
+
+	for scanner.Scan() {
+		line := scanner.Text() // note: newline removed
+		// re-append newline to preserve same output format
+		outLine := line + "\n"
+
+		// Write to intercepted channel if matching regexp
+		if i.prefixRegexp.MatchString(line) {
+			if _, err := io.WriteString(i.intercepted, outLine); err != nil {
+				i.logger.Errorf("intercept writer error: %v", err)
+			}
+		}
+		// Always write to target channel
+		if _, err := io.WriteString(i.target, outLine); err != nil {
+			i.logger.Errorf("writer error: %v", err)
+		}
+	}
+
+	// handle any scanner error
+	if err := scanner.Err(); err != nil {
+		i.logger.Errorf("router scanner error: %v\n", err)
+	}
+}

loginterceptor/loginterceptor_test.go

@@ -0,0 +1,72 @@
+package loginterceptor_test
+
+import (
+	"bytes"
+	"io"
+	"regexp"
+	"sync"
+	"testing"
+
+	"github.com/bitrise-io/go-utils/v2/log"
+	"github.com/bitrise-io/go-xcode/v2/loginterceptor"
+	"github.com/stretchr/testify/assert"
+)
+
+func TestPrefixInterceptor(t *testing.T) {
+	interceptReader, interceptWriter := io.Pipe()
+	targetReader, targetWriter := io.Pipe()
+	re := regexp.MustCompile(`^\[Bitrise.*\].*`)
+
+	sut := loginterceptor.NewPrefixInterceptor(re, interceptWriter, targetWriter, log.NewLogger())
+
+	msg1 := "Log message without prefix\n"
+	msg2 := "[Bitrise Analytics] Log message with prefix\n"
+	msg3 := "[Bitrise Build Cache] Log message with prefix\n"
+	msg4 := "Stuff [Bitrise Build Cache] Log message without prefix\n"
+
+	go func() {
+		//nolint:errCheck
+		defer sut.Close()
+
+		_, _ = sut.Write([]byte(msg1))
+		_, _ = sut.Write([]byte(msg2))
+		_, _ = sut.Write([]byte(msg3))
+		_, _ = sut.Write([]byte(msg4))
+	}()
+
+	intercepted, target, err := readTwo(interceptReader, targetReader)
+	assert.NoError(t, err)
+	assert.Equal(t, msg2+msg3, string(intercepted))
+	assert.Equal(t, msg1+msg2+msg3+msg4, string(target))
+}
+
+func readTwo(r1, r2 io.Reader) (out1, out2 []byte, err error) {
+	var (
+		wg     sync.WaitGroup
+		e1, e2 error
+	)
+	wg.Add(2)
+
+	var b1, b2 bytes.Buffer
+
+	go func() {
+		defer wg.Done()
+		_, e1 = io.Copy(&b1, r1)
+	}()
+
+	go func() {
+		defer wg.Done()
+		_, e2 = io.Copy(&b2, r2)
+	}()
+
+	wg.Wait()
+
+	// prefer to return the first non-nil error
+	if e1 != nil {
+		return b1.Bytes(), b2.Bytes(), e1
+	}
+	if e2 != nil {
+		return b1.Bytes(), b2.Bytes(), e2
+	}
+	return b1.Bytes(), b2.Bytes(), nil
+}

xcpretty/xcpretty.go

@@ -5,18 +5,21 @@ import (
 	"fmt"
 	"io"
 	"os"
+	"regexp"
 
 	"github.com/bitrise-io/go-steputils/v2/ruby"
 	loggerV1 "github.com/bitrise-io/go-utils/log"
 	"github.com/bitrise-io/go-utils/v2/command"
 	"github.com/bitrise-io/go-utils/v2/env"
 	"github.com/bitrise-io/go-utils/v2/log"
+	"github.com/bitrise-io/go-xcode/v2/loginterceptor"
 	"github.com/bitrise-io/go-xcode/v2/xcodebuild"
 	"github.com/hashicorp/go-version"
 )
 
 const (
 	toolName = "xcpretty"
+	prefixed = `^\[Bitrise.*\].*`
 )
 
 // CommandModel ...
@@ -53,17 +56,25 @@ func (c CommandModel) PrintableCmd() string {
 
 // Run ...
 func (c CommandModel) Run() (string, error) {
-
 	// Configure cmd in- and outputs
 	pipeReader, pipeWriter := io.Pipe()
 
 	var outBuffer bytes.Buffer
 	outWriter := io.MultiWriter(&outBuffer, pipeWriter)
 
+	logger := log.NewLogger()
+	re := regexp.MustCompile(prefixed)
+	interceptor := loginterceptor.NewPrefixInterceptor(re, os.Stdout, outWriter, logger)
+	defer func() {
+		if err := interceptor.Close(); err != nil {
+			logger.Warnf("Failed to close log interceptor, error: %s", err)
+		}
+	}()
+
 	xcodebuildCmd := c.xcodebuildCommand.Command(&command.Opts{
 		Stdin:  nil,
-		Stdout: outWriter,
-		Stderr: outWriter,
+		Stdout: interceptor,
+		Stderr: interceptor,
 	})
 
 	prettyCmd := c.Command(&command.Opts{