fix: executor logs (#781)

Signed-off-by: Timur Tuktamyshev <timur.tuktamyshev@flant.com>

Author: timmilesdw

pkg/executor/executor.go

@@ -216,52 +216,68 @@ func (pl *proxyLogger) Write(p []byte) (int, error) {
 		return len(p), nil
 	}
 
-	// logEntry.Log(log.FatalLevel, string(logLine))
 	pl.mergeAndLogInputLog(pl.ctx, logMap, "hook")
 
 	return len(p), nil
 }
 
 func (pl *proxyLogger) writerScanner(p []byte) {
 	scanner := bufio.NewScanner(bytes.NewReader(p))
-
-	// Set the buffer size to the maximum token size to avoid buffer overflows
 	scanner.Buffer(make([]byte, bufio.MaxScanTokenSize), bufio.MaxScanTokenSize)
 
-	// Define a split function to split the input into chunks of up to 64KB
+	var jsonBuf []string
+	// Split large entries into chunks
 	chunkSize := bufio.MaxScanTokenSize // 64KB
 	splitFunc := func(data []byte, atEOF bool) (int, []byte, error) {
 		if len(data) >= chunkSize {
 			return chunkSize, data[:chunkSize], nil
 		}
-
 		return bufio.ScanLines(data, atEOF)
 	}
-
-	// Use the custom split function to split the input
 	scanner.Split(splitFunc)
-
 	// Scan the input and write it to the logger using the specified print function
 	for scanner.Scan() {
-		// prevent empty logging
-		str := strings.TrimSpace(scanner.Text())
-		if str == "" {
+		// Prevent empty logging
+		line := strings.TrimSpace(scanner.Text())
+		if line == "" {
 			continue
 		}
 
-		if len(str) > 10000 {
-			str = fmt.Sprintf("%s:truncated", str[:10000])
+		if len(jsonBuf) > 0 || strings.HasPrefix(line, "{") {
+			jsonBuf = append(jsonBuf, line)
+			joined := strings.Join(jsonBuf, "\n")
+			if err := pl.tryLogJSON(joined); err == nil {
+				jsonBuf = nil
+			}
+			continue
 		}
 
-		pl.logger.Info(str)
-	}
+		if len(line) > 10000 {
+			line = fmt.Sprintf("%s:truncated", line[:10000])
+		}
 
+		if err := pl.tryLogJSON(line); err == nil {
+			continue
+		}
+		pl.logger.Info(line)
+	}
 	// If there was an error while scanning the input, log an error
 	if err := scanner.Err(); err != nil {
 		pl.logger.Error("reading from scanner", log.Err(err))
 	}
 }
 
+// tryLogJSON tries to parse the string as JSON and log it if it succeeds
+func (pl *proxyLogger) tryLogJSON(s string) error {
+	var m map[string]interface{}
+	err := json.Unmarshal([]byte(s), &m)
+	if err == nil {
+		pl.mergeAndLogInputLog(pl.ctx, m, "hook")
+		return nil
+	}
+	return fmt.Errorf("failed to parse json: %w", err)
+}
+
 // level = level
 // msg = msg
 // prefix for all fields hook_

pkg/executor/executor_test.go

@@ -3,10 +3,13 @@ package executor
 import (
 	"bytes"
 	"context"
+	"encoding/json"
+	"fmt"
 	"io"
 	"math/rand/v2"
 	"os"
 	"regexp"
+	"strings"
 	"testing"
 	"time"
 
@@ -69,7 +72,6 @@ func TestRunAndLogLines(t *testing.T) {
 
 		_, err = ex.RunAndLogLines(context.Background(), map[string]string{"a": "b"})
 		assert.NoError(t, err)
-
 		reg := regexp.MustCompile(`{"level":"info","msg":"hook result","a":"b","hook":{"truncated":".*:truncated"},"output":"stdout","proxyJsonLog":true,"time":"2006-01-02T15:04:05Z"`)
 		assert.Regexp(t, reg, buf.String())
 
@@ -105,9 +107,26 @@ func TestRunAndLogLines(t *testing.T) {
 
 		_, err := ex.RunAndLogLines(context.Background(), map[string]string{"a": "b"})
 		assert.NoError(t, err)
+		lines := strings.Split(strings.TrimSpace(buf.String()), "\n")
 
-		assert.Equal(t, buf.String(), `{"level":"debug","msg":"json log line not map[string]interface{}","source":"executor/executor.go:211","a":"b","line":["a","b","c"],"output":"stdout","time":"2006-01-02T15:04:05Z"}`+"\n"+
-			`{"level":"info","msg":"[\"a\",\"b\",\"c\"]\n","source":"executor/executor.go:214","a":"b","output":"stdout","time":"2006-01-02T15:04:05Z"}`+"\n")
+		var debugLine map[string]interface{}
+		err = json.Unmarshal([]byte(lines[0]), &debugLine)
+		assert.NoError(t, err)
+		assert.Equal(t, "debug", debugLine["level"])
+		assert.Equal(t, "json log line not map[string]interface{}", debugLine["msg"])
+		assert.Equal(t, []interface{}{"a", "b", "c"}, debugLine["line"])
+		assert.Equal(t, "b", debugLine["a"])
+		assert.Equal(t, "stdout", debugLine["output"])
+		assert.Equal(t, "2006-01-02T15:04:05Z", debugLine["time"])
+
+		var infoLine map[string]interface{}
+		err = json.Unmarshal([]byte(lines[1]), &infoLine)
+		assert.NoError(t, err)
+		assert.Equal(t, "info", infoLine["level"])
+		assert.Equal(t, "[\"a\",\"b\",\"c\"]\n", infoLine["msg"])
+		assert.Equal(t, "b", infoLine["a"])
+		assert.Equal(t, "stdout", infoLine["output"])
+		assert.Equal(t, "2006-01-02T15:04:05Z", infoLine["time"])
 		buf.Reset()
 	})
 
@@ -189,6 +208,37 @@ c d
 
 		buf.Reset()
 	})
+
+	t.Run("multiline json several logs", func(t *testing.T) {
+		logger.SetLevel(log.LevelInfo)
+		arg := `
+{"a":"b","c":"d"}
+{"b":"c","d":"a"}
+{"c":"d","a":"b"}
+{"d":"a","b":"c"}
+plain text
+{
+"a":"b",
+"c":"d"
+}`
+		ex := NewExecutor("", "echo", []string{arg}, []string{}).
+			WithLogProxyHookJSON(true).
+			WithLogger(logger)
+
+		_, err := ex.RunAndLogLines(context.Background(), map[string]string{"foor": "baar"})
+		assert.NoError(t, err)
+		fmt.Println("actual", buf.String())
+		expected := ""
+		expected += `{"level":"info","msg":"hook result","foor":"baar","hook_a":"b","hook_c":"d","output":"stdout","proxyJsonLog":true,"time":"2006-01-02T15:04:05Z"}` + "\n"
+		expected += `{"level":"info","msg":"hook result","foor":"baar","hook_b":"c","hook_d":"a","output":"stdout","proxyJsonLog":true,"time":"2006-01-02T15:04:05Z"}` + "\n"
+		expected += `{"level":"info","msg":"hook result","foor":"baar","hook_a":"b","hook_c":"d","output":"stdout","proxyJsonLog":true,"time":"2006-01-02T15:04:05Z"}` + "\n"
+		expected += `{"level":"info","msg":"hook result","foor":"baar","hook_b":"c","hook_d":"a","output":"stdout","proxyJsonLog":true,"time":"2006-01-02T15:04:05Z"}` + "\n"
+		expected += `{"level":"info","msg":"plain text","foor":"baar","output":"stdout","time":"2006-01-02T15:04:05Z"}` + "\n"
+		expected += `{"level":"info","msg":"hook result","foor":"baar","hook_a":"b","hook_c":"d","output":"stdout","proxyJsonLog":true,"time":"2006-01-02T15:04:05Z"}` + "\n"
+		assert.Equal(t, expected, buf.String())
+
+		buf.Reset()
+	})
 }
 
 var letterRunes = []rune("abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ")