diff --git a/export_test.go b/export_test.go index a89d7f2..99d5bae 100644 --- a/export_test.go +++ b/export_test.go @@ -4,6 +4,7 @@ import "io" var DefaultLogLevel = &defaultLogLevel +// Observers - func (los *logOutputSubject) Observers() ([]io.Writer, []Formatter) { los.mutObservers.RLock() defer los.mutObservers.RUnlock() @@ -11,6 +12,17 @@ func (los *logOutputSubject) Observers() ([]io.Writer, []Formatter) { 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) +} diff --git a/logOutputSubject.go b/logOutputSubject.go index b446136..cd1be4b 100644 --- a/logOutputSubject.go +++ b/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 { diff --git a/logOutputSubject_test.go b/logOutputSubject_test.go index 1c160c5..df4edc0 100644 --- a/logOutputSubject_test.go +++ b/logOutputSubject_test.go @@ -1,6 +1,8 @@ package logger_test import ( + "bytes" + "errors" "sync" "sync/atomic" "testing" @@ -8,9 +10,14 @@ import ( "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) + } + }) +} diff --git a/mock/formatterMock.go b/mock/formatterMock.go new file mode 100644 index 0000000..5cb5010 --- /dev/null +++ b/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 +}