log_test.go

// Copyright (c) 2021 Gitpod GmbH. All rights reserved.
// Licensed under the GNU Affero General Public License (AGPL).
// See License.AGPL.txt in the project root for license information.

package log

import (
	"bytes"
	"fmt"
	"io"
	"strings"
	"testing"
	"time"

	"github.com/google/go-cmp/cmp"
	"github.com/sirupsen/logrus"
)

func TestFromBuffer(t *testing.T) {
	tests := []struct {
		Description string
		Input       []byte
		Expected    []byte
	}{
		{
			"Empty",
			[]byte("\x00"),
			[]byte(""),
		},
		{
			"With null and without msg or message field",
			[]byte("\x00{\"notMessages\":\"\"}"),
			[]byte(""),
		},
		{
			"Output without msg or message field",
			[]byte("\x00{\"notMessages\":\"\"}"),
			[]byte(""),
		},
		{
			"Output with message field",
			[]byte("{\"level\":\"info\",\"message\":\"DisposeWorkspace called\",\"time\":\"2021-09-14T21:26:44Z\"}"),
			[]byte("{\"context\":\"test\",\"level\":\"info\",\"msg\":\"DisposeWorkspace called\",\"time\":\"2021-09-14T21:26:44Z\"}\n"),
		},
		{
			"Output with msg field",
			[]byte("{\"level\":\"info\",\"msg\":\"DisposeWorkspace called\",\"time\":\"2021-09-14T21:26:44Z\"}"),
			[]byte("{\"context\":\"test\",\"level\":\"info\",\"msg\":\"DisposeWorkspace called\",\"time\":\"2021-09-14T21:26:44Z\"}\n"),
		},
		{
			"Output with msg field and error level",
			[]byte("{\"level\":\"error\",\"message\":\"DisposeWorkspace called\",\"time\":\"2021-09-14T21:26:44Z\"}"),
			[]byte("{\"context\":\"test\",\"level\":\"error\",\"msg\":\"DisposeWorkspace called\",\"time\":\"2021-09-14T21:26:44Z\"}\n"),
		},
		{
			"Output with msg field and error level",
			[]byte("{\"level\":\"error\",\"message\":\"DisposeWorkspace called\",\"time\":\"2021-09-14T21:26:44Z\"}"),
			[]byte("{\"context\":\"test\",\"level\":\"error\",\"msg\":\"DisposeWorkspace called\",\"time\":\"2021-09-14T21:26:44Z\"}\n"),
		},
		{
			"With invalid JSON",
			[]byte("{\"notMessages\":\"\""),
			[]byte(""),
		},
		{
			"Text as JSON",
			[]byte("NOT JSON"),
			[]byte(""),
		},
		{
			"Mixed content - text and valid JSON",
			[]byte("SOMETHING INVALID\n{\"level\":\"error\",\"message\":\"DisposeWorkspace called\",\"time\":\"2021-09-14T21:26:44Z\"}"),
			[]byte("{\"context\":\"test\",\"level\":\"error\",\"msg\":\"DisposeWorkspace called\",\"time\":\"2021-09-14T21:26:44Z\"}\n"),
		},
	}

	for _, test := range tests {
		logger := logrus.New()
		var buffer bytes.Buffer
		logger.SetFormatter(&logrus.JSONFormatter{})
		logger.SetOutput(&buffer)
		logger.SetLevel(logrus.DebugLevel)

		entry := logger.WithField("context", "test")

		FromBuffer(bytes.NewBuffer(test.Input), entry)
		if diff := cmp.Diff(string(test.Expected), buffer.String()); diff != "" {
			t.Errorf("%v: unexpected result (-want +got):\n%s", test.Description, diff)
		}
	}
}

type TestWorkspaceInfo struct {
	WorkspaceId         string
	InstanceId          string
	WorkspaceContextUrl string
}

func TestScrubFormatter(t *testing.T) {
	logger := logrus.New()
	logger.SetFormatter(newGcpFormatter(false))

	var buffer bytes.Buffer
	logger.SetOutput(&buffer)

	createInfo := func() *TestWorkspaceInfo {
		return &TestWorkspaceInfo{
			WorkspaceId:         "1234567890",
			InstanceId:          "1234567890",
			WorkspaceContextUrl: "https://github.com/gitpod-io/gitpod",
		}
	}
	info := createInfo()
	workspaceID := "1234567890"

	logTime := time.Now()
	logger.WithTime(logTime).WithField("info", info).WithField("workspaceID", workspaceID).
		WithError(fmt.Errorf("some test error")).
		WithFields(ServiceContext("test", "1.0.0")).
		Info("email: [email protected]")

	expectation := fmt.Sprintf(
		`{"error":"some test error","info":"[redacted:nested]","level":"info","message":"email: [email protected]","serviceContext":{"service":"test","version":"1.0.0"},"severity":"INFO","time":"%s","workspaceID":"[redacted:md5:e807f1fcf82d132f9bb018ca6738a19f]"}`,
		logTime.Format(time.RFC3339Nano),
	)
	actual := strings.TrimSpace(buffer.String())
	if diff := cmp.Diff(expectation, actual); diff != "" {
		t.Errorf("unexpected result (-want +got):\n%s", diff)
	}
	if diff := cmp.Diff(createInfo(), info); diff != "" {
		t.Errorf("info: unexpected result (-want +got):\n%s", diff)
	}
	if diff := cmp.Diff("1234567890", workspaceID); diff != "" {
		t.Errorf("workspaceID: unexpected result (-want +got):\n%s", diff)
	}
}

/*
12/06/2023 - no cahce fields
cpu: Intel(R) Xeon(R) Platinum 8375C CPU @ 2.90GHz
BenchmarkSimpleScrubFormatter/json-32         	  312109	      3617 ns/op	    2035 B/op	      31 allocs/op
BenchmarkSimpleScrubFormatter/scrub+json-32   	  244150	      4753 ns/op	    2242 B/op	      37 allocs/op

09/06/2023 - with redacting nested fields
cpu: Intel(R) Xeon(R) Platinum 8375C CPU @ 2.90GHz
BenchmarkSimpleScrubFormatter/json-32         	  281763	      3666 ns/op	    2035 B/op	      31 allocs/op
BenchmarkSimpleScrubFormatter/scrub+json-32   	  278829	      4248 ns/op	    2204 B/op	      37 allocs/op

05/06/2023 - with json scrubbing
cpu: Intel(R) Xeon(R) Platinum 8375C CPU @ 2.90GHz
BenchmarkSimpleScrubFormatter/json-32         	  321686	      3546 ns/op	    2035 B/op	      31 allocs/op
BenchmarkSimpleScrubFormatter/scrub+json-32   	  148384	      8308 ns/op	    3781 B/op	      76 allocs/op

02/06/2023 (Intel(R) Xeon(R) Platinum 8375C CPU @ 2.90GHz) - with cache lock and eviction
BenchmarkSimpleScrubFormatter/json-32         	  359746	      3144 ns/op	    1914 B/op	      28 allocs/op
BenchmarkSimpleScrubFormatter/scrub+json-32   	  312946	      3796 ns/op	    2083 B/op	      34 allocs/op

02/06/2023 (Intel(R) Xeon(R) Platinum 8375C CPU @ 2.90GHz) - precomputed cache
BenchmarkSimpleScrubFormatter/json-32         	  367134	      3215 ns/op	    1914 B/op	      28 allocs/op
BenchmarkSimpleScrubFormatter/scrub+json-32   	  302583	      3869 ns/op	    2083 B/op	      34 allocs/op

01/06/2023 (Intel(R) Xeon(R) Platinum 8375C CPU @ 2.90GHz) - with caching without lower case conversion
BenchmarkSimpleScrubFormatter/json-32         	  377443	      3059 ns/op	    1914 B/op	      28 allocs/op
BenchmarkSimpleScrubFormatter/scrub+json-32   	  311752	      3704 ns/op	    2083 B/op	      34 allocs/op

31/05/2023 (Intel(R) Xeon(R) Platinum 8375C CPU @ 2.90GHz) - skip message, scrub with KeyValue for string type
BenchmarkSimpleScrubFormatter/json-32         	  376062	      3019 ns/op	    1914 B/op	      28 allocs/op
BenchmarkSimpleScrubFormatter/scrub+json-32   	  313464	      3798 ns/op	    2097 B/op	      35 allocs/op

31/05/2023 (Intel(R) Xeon(R) Platinum 8375C CPU @ 2.90GHz) - skip message
BenchmarkSimpleScrubFormatter/json-32         	  380050	      2991 ns/op	    1914 B/op	      28 allocs/op
BenchmarkSimpleScrubFormatter/scrub+json-32   	  270021	      4420 ns/op	    2233 B/op	      43 allocs/op

30/05/2023 (Intel(R) Xeon(R) Platinum 8375C CPU @ 2.90GHz) - scrubbing takes almost twice as long because of relection and regex replacements
BenchmarkSimpleScrubFormatter/json-32         	  368532	      3095 ns/op	    1914 B/op	      28 allocs/op
BenchmarkSimpleScrubFormatter/scrub+json-32   	  200944	      5858 ns/op	    2666 B/op	      53 allocs/op
0      1.21s (flat, cum) 38.29% of Total
.          .     94:func (formatter *scrubFormatter) Format(entry *logrus.Entry) ([]byte, error) {
.      300ms     95:   entry.Message = scrubber.Default.Value(entry.Message)
.      260ms     96:   err := scrubber.Default.Struct(entry.Data)
.          .     97:   if err != nil {
.          .     98:           return nil, fmt.Errorf("cannot scrub log entry: %w", err)
.          .     99:   }
.      650ms    100:   return formatter.delegate.Format(entry)
.          .    101:}
*/
func BenchmarkSimpleScrubFormatter(b *testing.B) {
	logger := logrus.New()
	logger.SetOutput(io.Discard)

	run := func() {
		logger.WithField("workspaceID", "1234567890").Info("email: [email protected]")
	}

	logger.SetFormatter(newGcpFormatter(true))
	b.Run("json", func(b *testing.B) {
		for i := 0; i < b.N; i++ {
			run()
		}
	})

	logger.SetFormatter(newGcpFormatter(false))
	b.Run("scrub+json", func(b *testing.B) {
		for i := 0; i < b.N; i++ {
			run()
		}
	})

}

/*
12/06/2023 - no cahce fields
cpu: Intel(R) Xeon(R) Platinum 8375C CPU @ 2.90GHz
BenchmarkStructScrubFormatter/json-32         	  304662	      3860 ns/op	    2091 B/op	      32 allocs/op
BenchmarkStructScrubFormatter/scrub+json-32   	  320354	      3698 ns/op	    2091 B/op	      32 allocs/op

09/06/2023 - with redacting nested fields
cpu: Intel(R) Xeon(R) Platinum 8375C CPU @ 2.90GHz
BenchmarkStructScrubFormatter/json-32         	  315826	      3706 ns/op	    2091 B/op	      32 allocs/op
BenchmarkStructScrubFormatter/scrub+json-32   	  322910	      3647 ns/op	    2091 B/op	      32 allocs/op

05/06/2023 - with json scrubbing
cpu: Intel(R) Xeon(R) Platinum 8375C CPU @ 2.90GHz
BenchmarkStructScrubFormatter/json-32         	  310472	      3842 ns/op	    2091 B/op	      32 allocs/op
BenchmarkStructScrubFormatter/scrub+json-32   	  109390	     10808 ns/op	    5101 B/op	     105 allocs/op

02/06/2023 (Intel(R) Xeon(R) Platinum 8375C CPU @ 2.90GHz - with cache lock and eviction
BenchmarkStructScrubFormatter/json-32         	  354174	      3314 ns/op	    1971 B/op	      29 allocs/op
BenchmarkStructScrubFormatter/scrub+json-32   	  242992	      4896 ns/op	    2365 B/op	      44 allocs/op

02/06/2023 (Intel(R) Xeon(R) Platinum 8375C CPU @ 2.90GHz - precomputed cache
BenchmarkStructScrubFormatter/json-32         	  344023	      3465 ns/op	    1971 B/op	      29 allocs/op
BenchmarkStructScrubFormatter/scrub+json-32   	  240534	      4850 ns/op	    2365 B/op	      44 allocs/op

01/06/2023 (Intel(R) Xeon(R) Platinum 8375C CPU @ 2.90GHz) - with caching without lower case conversion
BenchmarkStructScrubFormatter/json-32         	  354729	      3259 ns/op	    1971 B/op	      29 allocs/op
BenchmarkStructScrubFormatter/scrub+json-32   	  232270	      4767 ns/op	    2365 B/op	      44 allocs/op

01/06/2023 (Intel(R) Xeon(R) Platinum 8375C CPU @ 2.90GHz) - with substring mathing - 3 times slower
BenchmarkStructScrubFormatter/json-32         	  351439	      3388 ns/op	    1971 B/op	      29 allocs/op
BenchmarkStructScrubFormatter/scrub+json-32   	  115599	      9032 ns/op	    2396 B/op	      44 allocs/op

31/05/2023 (Intel(R) Xeon(R) Platinum 8375C CPU @ 2.90GHz) - early exit with SkipEntry + no double traversing
BenchmarkStructScrubFormatter/json-32         	  369788	      3885 ns/op	    1971 B/op	      29 allocs/op
BenchmarkStructScrubFormatter/scrub+json-32   	  232442	      5092 ns/op	    2421 B/op	      47 allocs/op

31/05/2023 (Intel(R) Xeon(R) Platinum 8375C CPU @ 2.90GHz) - initial, still double
BenchmarkStructScrubFormatter/json-32         	  349736	      3240 ns/op	    1971 B/op	      29 allocs/op
BenchmarkStructScrubFormatter/scrub+json-32   	  142266	      8295 ns/op	    2580 B/op	      53 allocs/op
*/
func BenchmarkStructScrubFormatter(b *testing.B) {
	logger := logrus.New()
	logger.SetOutput(io.Discard)

	run := func() {
		logger.WithField("info", &TestWorkspaceInfo{
			WorkspaceId:         "1234567890",
			InstanceId:          "1234567890",
			WorkspaceContextUrl: "https://github.com/gitpod-io/gitpod",
		}).Info("resolve workspace info failed")
	}

	logger.SetFormatter(newGcpFormatter(true))
	b.Run("json", func(b *testing.B) {
		for i := 0; i < b.N; i++ {
			run()
		}
	})

	logger.SetFormatter(newGcpFormatter(false))
	b.Run("scrub+json", func(b *testing.B) {
		for i := 0; i < b.N; i++ {
			run()
		}
	})

}