Merge pull request #12 from ElrondNetwork/protection-for-non-ascii-st…

…rings

Added protection for non ASCII strings

export_test.go

@@ -4,13 +4,25 @@ import "io"
 
 var DefaultLogLevel = &defaultLogLevel
 
+// Observers -
 func (los *logOutputSubject) Observers() ([]io.Writer, []Formatter) {
 	los.mutObservers.RLock()
 	defer los.mutObservers.RUnlock()
 
 	return los.writers, los.formatters
 }
 
+// LogLevel -
 func (l *logger) LogLevel() LogLevel {
 	return l.logLevel
 }
+
+// IsASCII -
+func IsASCII(data string) bool {
+	return isASCII(data)
+}
+
+// ConvertLogLine -
+func (los *logOutputSubject) ConvertLogLine(logLine *LogLine) LogLineHandler {
+	return los.convertLogLine(logLine)
+}

logOutputSubject.go

@@ -4,10 +4,16 @@ import (
 	"fmt"
 	"io"
 	"sync"
+	"unicode/utf8"
 
 	"github.com/ElrondNetwork/elrond-go-core/core/check"
 )
 
+const ASCIISpace = byte(' ')
+const ASCIITab = byte('\t')
+const ASCIILineFeed = byte('\r')
+const ASCIINewLine = byte('\n')
+
 var _ LogOutputHandler = (*logOutputSubject)(nil)
 
 // logOutputSubject follows the observer-subject pattern by which it holds n Writer and n Formatters.
@@ -62,6 +68,8 @@ func (los *logOutputSubject) convertLogLine(logLine *LogLine) LogLineHandler {
 		switch obj := obj.(type) {
 		case []byte:
 			line.Args[i] = displayHandler(obj)
+		case string:
+			line.Args[i] = convertStringIfNotASCII(displayHandler, obj)
 		default:
 			line.Args[i] = fmt.Sprintf("%v", obj)
 		}
@@ -70,6 +78,34 @@ func (los *logOutputSubject) convertLogLine(logLine *LogLine) LogLineHandler {
 	return line
 }
 
+func convertStringIfNotASCII(byteHandler func([]byte) string, data string) string {
+	if isASCII(data) {
+		return data
+	}
+
+	return byteHandler([]byte(data))
+}
+
+func isASCII(data string) bool {
+	for i := 0; i < len(data); i++ {
+		if data[i] >= utf8.RuneSelf {
+			return false
+		}
+
+		if data[i] >= ASCIISpace {
+			continue
+		}
+
+		if data[i] == ASCIITab || data[i] == ASCIILineFeed || data[i] == ASCIINewLine {
+			continue
+		}
+
+		return false
+	}
+
+	return true
+}
+
 // AddObserver adds a writer + formatter (called here observer) to the containing observer-like lists
 func (los *logOutputSubject) AddObserver(w io.Writer, format Formatter) error {
 	if w == nil {

logOutputSubject_test.go

@@ -1,16 +1,23 @@
 package logger_test
 
 import (
+	"bytes"
+	"errors"
 	"sync"
 	"sync/atomic"
 	"testing"
 	"time"
 
 	"github.com/ElrondNetwork/elrond-go-logger"
 	"github.com/ElrondNetwork/elrond-go-logger/mock"
+	"github.com/ElrondNetwork/elrond-go-logger/proto"
 	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
 )
 
+const testASCIIString = "DEBUG[2022-03-28 13:22:34.061] [consensus/spos/bls] [2/0/2/(END_ROUND)] step 3: block header final info has been received PubKeysBitmap = 1f AggregateSignature = 25f831bdb0801891a46b3b08a7bb11e306ad2e21d801a17312402a9d8bfc3ba76a4b97b42a8bc5ef533c471c47274c18 LeaderSignature = b2036b8db0bcaa7336e38f940b5f88706dc30afb6324693d01a93e9c47776ded31a195ac081b0c4274ed5c1354815292\n"
+const testNonASCIIString = "DEBUG[2022-03-28 13:22:34.027] [..cess/coordinator] [2/0/2/(BLOCK)] elapsed time to processMiniBlocksToMe    time [s] = 90.747µs \n"
+
 func TestNewLogOutputSubject(t *testing.T) {
 	t.Parallel()
 
@@ -19,7 +26,7 @@ func TestNewLogOutputSubject(t *testing.T) {
 	assert.False(t, los.IsInterfaceNil())
 }
 
-//------- AddObserver
+// ------- AddObserver
 
 func TestLogOutputSubject_AddObserverNilWriterShouldError(t *testing.T) {
 	t.Parallel()
@@ -54,7 +61,7 @@ func TestLogOutputSubject_AddObserverShouldWork(t *testing.T) {
 	assert.Equal(t, 1, len(formatters))
 }
 
-//------- Output
+// ------- Output
 
 func TestLogOutputSubject_OutputNoObserversShouldDoNothing(t *testing.T) {
 	t.Parallel()
@@ -91,6 +98,47 @@ func TestLogOutputSubject_OutputShouldCallFormatterAndWriter(t *testing.T) {
 	assert.Equal(t, int32(1), atomic.LoadInt32(&formatterCalled))
 }
 
+func TestLogOutputSubject_OutputShouldProduceCorrectString(t *testing.T) {
+	t.Parallel()
+
+	los := logger.NewLogOutputSubject()
+	var writtenData []byte
+	_ = los.AddObserver(
+		&mock.WriterStub{
+			WriteCalled: func(p []byte) (n int, err error) {
+				writtenData = p
+				return 0, nil
+			},
+		},
+		&mock.FormatterMock{},
+	)
+
+	logLine := &logger.LogLine{
+		LoggerName:  "",
+		Correlation: proto.LogCorrelationMessage{},
+		Message:     "message",
+		LogLevel:    logger.LogDebug,
+		Args: []interface{}{
+			"int", 1,
+			"ASCII string", "plain text \n",
+			"non-ASCII string", "µs",
+			"time.Duration", time.Microsecond*4 + time.Nanosecond,
+			"byte slice", []byte("aaa"),
+			"error", errors.New("an error"),
+			"bool", true,
+		},
+		Timestamp: time.Date(2022, 03, 30, 15, 47, 52, 0, time.Local),
+	}
+
+	los.Output(logLine)
+
+	expectedString := `DEBUG[2022-03-30 15:47:52.000]   message                                  int = 1 ASCII string = plain text 
+ non-ASCII string = c382c2b573 time.Duration = 4.001µs byte slice = 616161 error = an error bool = true 
+`
+
+	assert.Equal(t, expectedString, string(writtenData))
+}
+
 func TestLogOutputSubject_OutputCalledConcurrentShouldWork(t *testing.T) {
 	t.Parallel()
 
@@ -129,7 +177,7 @@ func TestLogOutputSubject_OutputCalledConcurrentShouldWork(t *testing.T) {
 	assert.Equal(t, int32(numCalls), atomic.LoadInt32(&formatterCalled))
 }
 
-//------- RemoveObserver
+// ------- RemoveObserver
 
 func TestLogOutputSubject_RemoveObserverNilWriterShouldError(t *testing.T) {
 	t.Parallel()
@@ -227,3 +275,81 @@ func TestLogOutputSubject_ClearObservers(t *testing.T) {
 	obs, _ = los.Observers()
 	assert.Equal(t, 0, len(obs))
 }
+
+func TestIsASCII(t *testing.T) {
+	t.Parallel()
+
+	tableString := `
++---------+---------+
+| header1 | header2 |
++---------+---------+
+| aaa     | bbb     |
+| ccc     | ddd     |
++---------+---------+
+| eee     | fff     |
++---------+---------+
+`
+
+	assert.True(t, logger.IsASCII(tableString))
+	assert.True(t, logger.IsASCII("ascii TEXT.,/?\"@~#$%^&*()_+[]{} 1234 \\\t\n"))
+	assert.False(t, logger.IsASCII("µs"))
+	assert.True(t, logger.IsASCII(testASCIIString))
+	assert.False(t, logger.IsASCII(testNonASCIIString))
+}
+
+func TestLogOutputSubject_variousTypesOfStrings(t *testing.T) {
+	t.Parallel()
+
+	// ASCII string
+	testArgFormat(t, "test", "test")
+
+	// a hash
+	hash := bytes.Repeat([]byte{1}, 32)
+	expectedRes := "0101010101010101010101010101010101010101010101010101010101010101"
+	testArgFormat(t, hash, expectedRes)
+
+	// emojis
+	emojiString := "🏓🏓🏓"
+	expectedRes = "f09f8f93f09f8f93f09f8f93"
+	testArgFormat(t, emojiString, expectedRes)
+
+	// a data field
+	dataField := "ESDTTransfer@6y7u8i@1000"
+	testArgFormat(t, dataField, dataField)
+
+	// bytes should be returned as hex representation
+	uglyBytes := []byte{0, 5, 17, 19, 127}
+	expectedRes = "000511137f"
+	testArgFormat(t, uglyBytes, expectedRes)
+
+	// non-ASCII characters as string
+	uglyString := string(uglyBytes)
+	expectedRes = "000511137f"
+	testArgFormat(t, uglyString, expectedRes)
+}
+
+func testArgFormat(t *testing.T, input interface{}, expectedOutput interface{}) {
+	los := logger.NewLogOutputSubject()
+
+	logLine := logger.LogLine{
+		Args: []interface{}{"test key", input},
+	}
+
+	result := los.ConvertLogLine(&logLine)
+	require.Equal(t, expectedOutput, result.GetArgs()[1])
+}
+
+func BenchmarkIsASCII(b *testing.B) {
+	b.Run("ASCII string", func(b *testing.B) {
+		// should be < 170ns/op for the provided string
+		for i := 0; i < b.N; i++ {
+			_ = logger.IsASCII(testASCIIString)
+		}
+	})
+	b.Run("non ASCII string", func(b *testing.B) {
+		// should be < 60ns/op for the provided string
+		for i := 0; i < b.N; i++ {
+			_ = logger.IsASCII(testNonASCIIString)
+		}
+	})
+}

mock/formatterMock.go

@@ -0,0 +1,74 @@
+package mock
+
+import (
+	"fmt"
+	"strings"
+	"time"
+
+	logger "github.com/ElrondNetwork/elrond-go-logger"
+)
+
+const messageFixedLength = 40
+const formatPlainString = "%s[%s] %s %s %s %s\n"
+
+type FormatterMock struct {
+}
+
+// Output converts the provided LogLineHandler into a slice of bytes ready for output
+func (mock *FormatterMock) Output(line logger.LogLineHandler) []byte {
+	if line == nil {
+		return nil
+	}
+
+	level := logger.LogLevel(line.GetLogLevel())
+	timestamp := displayTime(line.GetTimestamp())
+	loggerName := ""
+	correlation := ""
+	message := formatMessage(line.GetMessage())
+	args := formatArgsNoAnsi(line.GetArgs()...)
+
+	return []byte(
+		fmt.Sprintf(formatPlainString,
+			level,
+			timestamp, loggerName, correlation,
+			message, args,
+		),
+	)
+}
+
+// IsInterfaceNil returns true if there is no value under the interface
+func (mock *FormatterMock) IsInterfaceNil() bool {
+	return mock == nil
+}
+
+func displayTime(timestamp int64) string {
+	t := time.Unix(0, timestamp)
+	return t.Format("2006-01-02 15:04:05.000")
+}
+
+func formatArgsNoAnsi(args ...string) string {
+	if len(args) == 0 {
+		return ""
+	}
+
+	argString := ""
+	for index := 1; index < len(args); index += 2 {
+		argString += fmt.Sprintf("%s = %s ", args[index-1], args[index])
+	}
+
+	return argString
+}
+
+func formatMessage(msg string) string {
+	return padRight(msg, messageFixedLength)
+}
+
+func padRight(str string, maxLength int) string {
+	paddingLength := maxLength - len(str)
+
+	if paddingLength > 0 {
+		return str + strings.Repeat(" ", paddingLength)
+	}
+
+	return str
+}