Bugfix for log lines without or delayed newlines results in a file truncated detection and reading the file again #164

tzahari · 2014-02-17T10:19:30Z

Changed the file reading from ReadLine() to ReadBytes('\n').
Now the file is not longer recognized as truncated (and start reading the file again from the beginning).
Details here: #149

The problem is that ReadLine() http://golang.org/pkg/bufio/#Reader.ReadLine returns also a incomplete line (without newline) but there is no indicator that the newline is missing.
Therefor I changed the reading to ReadBytes() http://golang.org/pkg/bufio/#Reader.ReadBytes

I found a solution for the issue elastic#149

driskell · 2014-02-25T09:25:10Z

Just for reference, as described in #149 we discovered ReadLine() actually treats EOF as an end-of-line delimiter (I checked the pkg source) - which is the root cause of the issue.

driskell · 2014-02-28T12:42:21Z

Hi tzahari,
Looks like this won't work properly with resume as the +1 still needs to be there on the offset.
Offset will be behind by a number of bytes equal to the number of lines previously imported.
I've not tested this hypothesis but it seems to be the case running through the code...
Can you put the +1 back in and try it out?
Jason

driskell · 2014-02-28T13:13:47Z

I've been testing without the removal of +1 and it does work OK, no issue with the reproduction steps you provided before. So if you can put that +1 back in that will make this fix perfect :-)
Thanks for sorting it!

tzahari · 2014-02-28T13:24:16Z

Hi Jason,
Thanks for the hint. I am currently checking it and found a possible another issue on windows system with CRLF. The current version of the method would return the line with a CR. I think it would be better to remove this also.
What do you think?

driskell · 2014-02-28T14:09:22Z

Hi tzahari,

I agree. I think the best way seems to be, readline() returns another value - the number of characters stripped - and that is added to offset.

Jason.

driskell · 2014-02-28T16:15:13Z

Hi tzahari,

Found another possible issue - if the newline does not appear for more than 10 seconds, we lose all data up until the line because it's kept in buffer and we lose it when we return nil, io.EOF.

I think it need to do one of:

Before returning EOF after the timeout, seek back to the beginning of that line so the next call reads it again
More drastic... the buffer needs to be scoped to the caller so it can pass it back in on subsequent calls

Jason

Fixed: file offset still calculated wrong. File was detected as truncated again :-( Fixed: loosing the beginning of a partial line Fixed: A CR is also removed from the EOL Known issues: If the last line was logged with CRLF as EOF then the file offset is not correct calculated (missing one byte for the CR) in the Registry

tzahari · 2014-02-28T16:24:32Z

Hi Jason,
I fixed some more issues and tested a lot. tzahari@2c7d915
I'll hope everything is correct now.
Thanks for your response.
Best Regards
Thomas

driskell · 2014-02-28T16:33:25Z

Cool

That issue with the registrar... I've fixed that in my PR by moving the offset change to BEFORE the registrar event is sent. So the registrar actually has the calculated offset and doesn't need to do anything.

I'll drop a comment on one bit I'm not sure why was moved.

I've also got the tests working here so I can apply your PR to my PR, fix conflicts, and see if the test passes (currently fails of course!)

Regards

Jason

driskell · 2014-02-28T16:35:07Z

harvester.go

+    }
+
+    if segment != nil && len(segment) > 0 {
+


Line 145. Just needs blank line removing here and at end of block - forget what I said about moved - got it now, needed bufferSize earlier ^^ Coolios

driskell · 2014-02-28T18:27:21Z

Hi tzahari,

I got the tests working again and created a test, but it fails.
I just worked out the problem - the offset in the file is basically at EOF because the data is buffered.
ReadBytes is pulling from a buffer. So when we call readline(), we've already read the partial line. What we need is offset from the beginning of the partial line.

So looks like the buffer is gonna need to be held by the caller, Harvest() and it passes it back in on each subsequent call. If readline() returns a line it will need to clear the buffer (since it won't go out of scope anymore).

Jason

driskell · 2014-02-28T18:42:58Z

So I'm thinking if we do this in Harvest()

  // TODO(sissel): Make the buffer size tunable at start-time
  reader := bufio.NewReaderSize(h.file, 16<<10) // 16kb buffer by default
  buffer := new(bytes.Buffer)

  var read_timeout = 10 * time.Second
  last_read_time := time.Now()
  for {
    text, bytesread, err := h.readline(reader, buffer, read_timeout)

Then the later bit. Don't worry about the +1 in the registrar - my PR ultimately fixes it but its minor - with CRLF it just means we resume and read a blank line - no bad thing really

offset += int64(bytesread)

Then we have for readline()

func (h *Harvester) readline(reader *bufio.Reader, buffer *bytes.Buffer, eof_timeout time.Duration) (*string, int, error) {
  var is_partial bool = true
  var newline_length int = 1
  start_time := time.Now()

  for {
    segment, err := reader.ReadBytes('\n')

    if segment != nil && len(segment) > 0 {
      if segment[len(segment)-1] == '\n' {
        // Found a complete line
        is_partial = false

        // Check if also a CR present
        if len(segment) > 1 && segment[len(segment)-2] == '\r' {
          newline_length++
        }
      }

      // TODO(sissel): if buffer exceeds a certain length, maybe report an error condition? chop it?
      buffer.Write(segment)
    }

    if err != nil {
      if err == io.EOF && is_partial {
        time.Sleep(1 * time.Second) // TODO(sissel): Implement backoff

        // Give up waiting for data after a certain amount of time.
        // If we time out, return the error (eof)
        if time.Since(start_time) > eof_timeout {
          return nil, 0, err
        }
        continue
      } else {
        log.Println(err)
        return nil, 0, err // TODO(sissel): don't do this?
      }
    }

    // If we got a full line, return the whole line without the EOL chars (CRLF or LF)
    if !is_partial {
      // Get the str length with the EOL chars (LF or CRLF)
      bufferSize := buffer.Len()
      str := new(string)
      *str = buffer.String()[:bufferSize - newline_length]
      // Reset the buffer for the next line
      buffer.Reset()
      return str, bufferSize, nil
    }
  } /* forever read chunks */

  return nil, 0, nil
}

Using the above, the test I've made passes!

driskell · 2014-02-28T20:00:36Z

FYI - just updated my comment with the fixed code - I simplified the CRLF detection and fixed a few formatting bits

Thanks to https://github.com/driskell

tzahari · 2014-02-28T20:24:14Z

Hi Jason,
Thanks for your optimizations and help.
Do you have any ideas why the Travis CI build fails every time?
Have a nice weekend.
Thomas

driskell · 2014-02-28T20:32:36Z

No problem!
It's because the test suite is expecting newer gems than what the Gemspec.lock specifies.
And also because it still refers to lumberjack and not logstash-forwarder - looks like the rename wasn't finished for the tests.

I fixed it all though in another PR - and also added test cases for this issue and the couple others I fixed. That one doesn't fail because of the above reasons, it just fails because the tests fail (which is good!)

Once the test PR is merged, this one too, and my one, it should start succeeding. Although Jordan might kill me when he sees the conflicts lol... but when I did a test merge it didn't look too bad...

Have a good weekend too :-)
Thanks for letting everyone know the issue and its good to have it sorted!
I may email Jordan at some point if I can track down contact info and offer to merge the PRs for him so he can do one feel sweep - this is assuming he doesn't think my code is crap though :)

driskell · 2014-02-28T20:33:27Z

When I say merge the PR for him - I mean into one big PR. I'm not a maintainer! lol

glongman · 2014-03-21T12:50:01Z

any news of forward movement on this fix?

driskell · 2014-03-21T19:27:26Z

Hi glongman,
It's complete. Just needs merge.

You can find a fully working logstash-forwarder including this and more in my github:
Http://github.com/driskell/logstash-forwarder

jordansissel · 2014-03-21T19:36:29Z

Apologies for the delay in attending to many of these pull requests. The PRs now appear to be some kind of spaghetti of merges crossing into other PRs. My plan is to spend some time next week untangling what has occurred in my absence. Hopefully will have some of these things merged soon.

Thanks again for your patience!

danslimmon · 2014-04-14T19:20:32Z

I can confirm that this fix works. I've been using it for a week, and I haven't had any more floods of repeated log data.

jordansissel · 2014-05-05T18:08:48Z

harvester.go

  for {
-    segment, is_partial, err := reader.ReadLine()
+    segment, err := reader.ReadBytes('\n')


I haven't fully read this patch, but it looks like this reimplements go's ReadLine() method with respect to partial detection. Is there a bug we should file upstream to the Go developers? Put differently, what caused this to need reimplementing of is_partial?

As described in #149 we discovered ReadLine() actually treats EOF as an end-of-line delimiter (I checked the pkg source) - which is the root cause of the issue.
So if you have data at the end of the log, with no new line, ReadLine() returns normally with is_partial set to false and you can never know if there was a new line or not - and LSF assumes there was (the +1 we have for offset). So we end up offset too far ahead of the Size() and detect truncation, wrongly.

It's also worth noting http://golang.org/pkg/bufio/#Reader.ReadLine

ReadLine is a low-level line-reading primitive. Most callers should use ReadBytes('\n') or ReadString('\n') instead or use a Scanner.

Using ReadBytes('\n') we can safely ensure that we don't treat EOF as a line delimiter and properly count the \r\n bytes at the end.

I also think Go have documented the behaviour at EOF. Note the second sentence.

The text returned from ReadLine does not include the line end ("\r\n" or "\n"). No indication or error is given if the input ends without a final line end.

So an upstream patch is probably not viable as it's the defined behaviour.

tzahari · 2014-06-06T09:10:31Z

Hi @jordansissel ,
Can I support you to merge this pull request?
Do not hesitate to contact me.
Regards
Thomas

driskell · 2014-09-29T21:30:55Z

@twood9003 are you sure it's the same issue? This was a very specific issue and you haven't mentioned any of the symptoms you are seeing.

If you could raise a new issue it would be better and we can all look at it with fresh eyes in the event it is different. It helps too as this is now closed.

Bugfix for logging lines without or delayed newlines

2c7d915

I found a solution for the issue elastic#149

driskell mentioned this pull request Feb 25, 2014

Fix an off-by-one error when comparing file size #146

Closed

driskell mentioned this pull request Feb 28, 2014

Fix broken state w/ multiple logs; improve rename handling; add reconnect timeout option; resume old files; start from beginning of file if created after startup (same as LogStash) #151

Closed

driskell reviewed Feb 28, 2014
View reviewed changes

Small optimizations

eb6309a

Thanks to https://github.com/driskell

driskell mentioned this pull request Feb 28, 2014

Missing log entries in log rotated files #144

Closed

This was referenced Mar 19, 2014

Lumberjack send tons of data at file rotation and locks the old file #101

Closed

client logs unchanging,but repeatedly send the same logs to logstash server #131

Closed

driskell mentioned this pull request Mar 26, 2014

Logstash-forwarder sends the old logfile at logrotation #163

Closed

driskell mentioned this pull request Apr 7, 2014

lumberjack traffic creates an endless loop in conjunction with logstash #191

Closed

driskell mentioned this pull request Apr 22, 2014

Support for both Windows and Linux newlines and don't split lines #193

Closed

driskell mentioned this pull request May 5, 2014

#151 split down: Fix rotation and persistence issues and allow harvester to resume after dead time #201

Closed

jordansissel reviewed May 5, 2014
View reviewed changes

dasibre mentioned this pull request May 7, 2014

forwarder infinite loop THIS IS PROBABLY A DUPLICATE OF #164 Bug #203

Closed

driskell mentioned this pull request Jul 4, 2014

Logs duplicating every night, logstash forwarder + logrotate #176

Closed

jordansissel closed this in 3a92c11 Jul 10, 2014

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Bugfix for log lines without or delayed newlines results in a file truncated detection and reading the file again #164

Bugfix for log lines without or delayed newlines results in a file truncated detection and reading the file again #164

tzahari commented Feb 17, 2014

driskell commented Feb 25, 2014

driskell commented Feb 28, 2014

driskell commented Feb 28, 2014

tzahari commented Feb 28, 2014

driskell commented Feb 28, 2014

driskell commented Feb 28, 2014

tzahari commented Feb 28, 2014

driskell commented Feb 28, 2014

driskell Feb 28, 2014

driskell commented Feb 28, 2014

driskell commented Feb 28, 2014

driskell commented Feb 28, 2014

tzahari commented Feb 28, 2014

driskell commented Feb 28, 2014

driskell commented Feb 28, 2014

glongman commented Mar 21, 2014

driskell commented Mar 21, 2014

jordansissel commented Mar 21, 2014

danslimmon commented Apr 14, 2014

jordansissel May 5, 2014

driskell May 5, 2014

driskell May 5, 2014

tzahari commented Jun 6, 2014

driskell commented Sep 29, 2014

Bugfix for log lines without or delayed newlines results in a file truncated detection and reading the file again #164

Bugfix for log lines without or delayed newlines results in a file truncated detection and reading the file again #164

Conversation

tzahari commented Feb 17, 2014

driskell commented Feb 25, 2014

driskell commented Feb 28, 2014

driskell commented Feb 28, 2014

tzahari commented Feb 28, 2014

driskell commented Feb 28, 2014

driskell commented Feb 28, 2014

tzahari commented Feb 28, 2014

driskell commented Feb 28, 2014

driskell Feb 28, 2014

Choose a reason for hiding this comment

driskell commented Feb 28, 2014

driskell commented Feb 28, 2014

driskell commented Feb 28, 2014

tzahari commented Feb 28, 2014

driskell commented Feb 28, 2014

driskell commented Feb 28, 2014

glongman commented Mar 21, 2014

driskell commented Mar 21, 2014

jordansissel commented Mar 21, 2014

danslimmon commented Apr 14, 2014

jordansissel May 5, 2014

Choose a reason for hiding this comment

driskell May 5, 2014

Choose a reason for hiding this comment

driskell May 5, 2014

Choose a reason for hiding this comment

tzahari commented Jun 6, 2014

driskell commented Sep 29, 2014