Skip to content
New issue

Have a question about this project? # for a free GitHub account to open an issue and contact its maintainers and the community.

#

By clicking “#”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? # to your account

fix panic in Writer #1384

Closed
wants to merge 1 commit into from
Closed

fix panic in Writer #1384

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
8 changes: 4 additions & 4 deletions writer.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -70,16 +70,16 @@ func (entry *Entry) writerScanner(reader *io.PipeReader, printFunc func(args ...
scanner.Buffer(make([]byte, bufio.MaxScanTokenSize), bufio.MaxScanTokenSize)

// Define a split function to split the input into chunks of up to 64KB
chunkSize := 64 * 1024 // 64KB
chunkSize := bufio.MaxScanTokenSize // 64KB
splitFunc := func(data []byte, atEOF bool) (int, []byte, error) {
if len(data) > chunkSize {
if len(data) >= chunkSize {
return chunkSize, data[:chunkSize], nil
}

return len(data), data, nil
return bufio.ScanLines(data, atEOF)
}

//Use the custom split function to split the input
// 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
Expand Down
64 changes: 64 additions & 0 deletions writer_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,10 +1,16 @@
package logrus_test

import (
"bufio"
"bytes"
"log"
"net/http"
"strings"
"testing"
"time"

"github.com/sirupsen/logrus"
"github.com/stretchr/testify/assert"
)

func ExampleLogger_Writer_httpServer() {
Expand Down Expand Up @@ -32,3 +38,61 @@ func ExampleLogger_Writer_stdlib() {
// Not logrus imported under the name `log`.
log.SetOutput(logger.Writer())
}

func TestWriterSplitNewlines(t *testing.T) {
buf := bytes.NewBuffer(nil)
logger := logrus.New()
logger.Formatter = &logrus.TextFormatter{
DisableColors: true,
DisableTimestamp: true,
}
logger.SetOutput(buf)
writer := logger.Writer()

const logNum = 10

for i := 0; i < logNum; i++ {
_, err := writer.Write([]byte("bar\nfoo\n"))
assert.NoError(t, err, "writer.Write failed")
}
writer.Close()
// Test is flaky because it writes in another goroutine,
// we need to make sure to wait a bit so all write are done.
time.Sleep(500 * time.Millisecond)

lines := strings.Split(strings.TrimRight(buf.String(), "\n"), "\n")
assert.Len(t, lines, logNum*2, "logger printed incorrect number of lines")
}

func TestWriterSplitsMax64KB(t *testing.T) {
buf := bytes.NewBuffer(nil)
logger := logrus.New()
logger.Formatter = &logrus.TextFormatter{
DisableColors: true,
DisableTimestamp: true,
}
logger.SetOutput(buf)
writer := logger.Writer()

// write more than 64KB
const bigWriteLen = bufio.MaxScanTokenSize + 100
output := make([]byte, bigWriteLen)
// lets not write zero bytes
for i := 0; i < bigWriteLen; i++ {
output[i] = 'A'
}

for i := 0; i < 3; i++ {
len, err := writer.Write(output)
assert.NoError(t, err, "writer.Write failed")
assert.Equal(t, bigWriteLen, len, "bytes written")
}
writer.Close()
// Test is flaky because it writes in another goroutine,
// we need to make sure to wait a bit so all write are done.
time.Sleep(500 * time.Millisecond)

lines := strings.Split(strings.TrimRight(buf.String(), "\n"), "\n")
// we should have 4 lines because we wrote more than 64 KB each time
assert.Len(t, lines, 4, "logger printed incorrect number of lines")
Copy link
Owner

@sirupsen sirupsen May 21, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hey! Thank you for fixing this (I had to revert the other commit in master, because of this panic). Let's get this fixed properly.

I think there's two ways of dealing with this, and I'm interested in your take (and those on the original issue @kke @brahads @ozfive @ashmckenzie @scarroll32 @voidspooks).

Intuitively, I would expect this to yield 6 log lines:

# approach 1
line1: 1024 * 64 * A
line2: 100 * A
line3: 1024 * 64 * A
line4: 100 * A
line5: 1024 * 64 * A
line6: 100 * A

But, this implementation from @ozfive yields:

# approach 2 (implemented)
line1: 1024 * 64 * A
line2: 1024 * 64 * A 
line3: 1024 * 64 * A
line4: 300 * A

In other words, log lines bleed into each other. The As from line1 bleed into line2, and so on.

I prefer approach 1, this seems way more intuitive to me when reading logs.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I personally do not care much, the current behavior is to only split at newlines. So if you write something without a newline at the end it also buffered it like we do now.

I am fine with changing the behavior to approach 1 but at that point we might as well just do not use the Scanner at all and exec the print function for each Write() call the caller makes, in this case we do not need to worry about the scanner limitations at all and do not need extra buffers.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@sirupsen bumping this. I agree with @Luap99's explanation though.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It would be great if we can put a fix for the panic soon so that we can upgrade to a version without the DoS vulnerability that's described in #1370

Copy link
Contributor

@ashmckenzie ashmckenzie Jun 2, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sorry for the delay @sirupsen (was on vacation 😉), using the following test program:

package main

import (
	"bufio"
	"strings"
	"time"

	logrus "github.com/sirupsen/logrus"
)

func main() {
	output1 := strings.Repeat("A", bufio.MaxScanTokenSize) + "Z"
	output2 := strings.Repeat("B", bufio.MaxScanTokenSize) + "Z"

	logger := logrus.New()
	writer := logger.Writer()

	writer.Write([]byte("start"))
	writer.Write([]byte(output1))
	writer.Write([]byte(output2))
	writer.Write([]byte("end"))

	writer.Close()

	time.Sleep(500 * time.Millisecond)
}

as well as an updated writerScanner() function:

func (entry *Entry) writerScanner(reader *io.PipeReader, printFunc func(args ...interface{})) {
	for {
		data := make([]byte, bufio.MaxScanTokenSize)
		c, err := reader.Read(data)
		if err != nil && err != io.EOF {
			entry.Errorf("Error while reading from Writer: %s", err)
			break
		}

		if c > 0 {
			chunks := strings.Split(strings.TrimRight(string(bytes.Trim(data, "\x00")), "\n"), "\n")
			for _, section := range chunks {
				printFunc(section)
			}
		}
	}

	// Close the reader when we are done
	reader.Close()
}

I believe this achieves the preferred # approach 1:

$ go run play.go 2>&1
time="2023-06-02T22:06:34+10:00" level=info msg=start
time="2023-06-02T22:06:34+10:00" level=info msg=A<lots of As>
time="2023-06-02T22:06:34+10:00" level=info msg=Z
time="2023-06-02T22:06:34+10:00" level=info msg=B<lots of Bs>
time="2023-06-02T22:06:34+10:00" level=info msg=Z
time="2023-06-02T22:06:34+10:00" level=info msg=end

Am just updating the TestWriterSplitsMax64KB() test in a new branch to demonstrate. WDYT?

}