mozilla-services/heka — pull request #1219 by dcarley (2014-12-10 12:03:11+00:00)
Title: Fix logstreamer journal saving loop

Supersedes #1215. Rebased against 0.8 branch and changelog entry added.

---

`LogstreamerInput` keeps repeatably writing the same journal entry to disk
when it reaches the end of a log file. This puts a lot of strain on the disk
where the journal files are located, eg. 100 monitored log files results in
400 IOPS (write).

Fix this by not calling `SavePosition()` if `Logstream` surfaces an `io.EOF`
error, because `Logstream` already saves the position when it reaches EOF
and keeps track of this so as to prevent unnecessary saves when the file
isn't advancing.

As discussed in the PR we still want to save in all other cases, such as
other errors or a stop channel event, and always reset the `recordCount`
accordingly.

The issue can be demonstrated with the following config:

[test_input]
type = "LogstreamerInput"
parser_type = "token"
log_directory = "/var/log/heka_test"
file_match = '(?P.+)\.log'
differentiator = ["test_input.", "Name"]
priority = ["^Index"]

Writing a single line to a matching file and monitoring writes using `sysdig`
shows a journal entry with the same `seek` and `last_hash` values being written
every 0.25 seconds:

root@graphite-1:~# echo hello world > /var/log/heka_test/1.log
root@graphite-1:~# sysdig -c spy_file "fd.directory=/var/cache/hekad/logstreamer/"
22:26:47.955585858 hekad(18141) W 105B /var/cache/hekad/logstreamer/test_input.1
{\"seek\":12,\"file_name\":\"/var/log/heka_test/1.log\",\"last_hash\":\"a7cdf03790426606e33f154d67771842c48dcf83\"}
22:26:48.206101677 hekad(18141) W 105B /var/cache/hekad/logstreamer/test_input.1
{\"seek\":12,\"file_name\":\"/var/log/heka_test/1.log\",\"last_hash\":\"a7cdf03790426606e33f154d67771842c48dcf83\"}
22:26:48.456563080 hekad(18141) W 105B /var/cache/hekad/logstreamer/test_input.1
{\"seek\":12,\"file_name\":\"/var/log/heka_test/1.log\",\"last_hash\":\"a7cdf03790426606e33f154d67771842c48dcf83\"}
22:26:48.706010894 hekad(18141) W 105B /var/cache/hekad/logstreamer/test_input.1
{\"seek\":12,\"file_name\":\"/var/log/heka_test/1.log\",\"last_hash\":\"a7cdf03790426606e33f154d67771842c48dcf83\"}
22:26:48.956700377 hekad(18141) W 105B /var/cache/hekad/logstreamer/test_input.1
{\"seek\":12,\"file_name\":\"/var/log/heka_test/1.log\",\"last_hash\":\"a7cdf03790426606e33f154d67771842c48dcf83\"}
22:26:49.206755665 hekad(18141) W 105B /var/cache/hekad/logstreamer/test_input.1
{\"seek\":12,\"file_name\":\"/var/log/heka_test/1.log\",\"last_hash\":\"a7cdf03790426606e33f154d67771842c48dcf83\"}