File rotation

[Justin Davis]

Hi!

Question about file rotation -- I was running dendrite last night, left it running and when the log file I was watching rotated. Dendrite stopped processing this file -- any thoughts on how to best handle log rotation?

Thanks!
-Justin

[Kyle Maxwell]

Here's the code to handle rotation.  If the tail hits eof, and the file is shorter than last recorded, the tail will start over.

https://github.com/onemorecloud/dendrite/blob/master/src/dendrite/tail.go#L143

I have an integration test that reads a file, truncates it, and re-writes it.  It verifies that the contents get read twice.

https://github.com/onemorecloud/dendrite/blob/master/dendrite_test.go#L40

Our production use is so far on files that rotate forwards (e.g. foo.2013.01.01.log), so its possible that there's a bug in this code.  Minimal instructions to reproduce the bug would be greatly appreciated.

--
Cheers,
Kyle Maxwell
Founder, Onemorecloud, Inc
bonsai.io | websolr.com
ky...@onemorecloud.com

[Justin Davis]

Got it, I'll try to reproduce and investigate that code some more.

[Justin Davis]

Alright, happened again... I'll do some more investigation when I have some free time, but here's a quick data point: I checked out /proc/PID of the dendrite process, and did an ls in the fd folder, and got this:

lr-x------ 1 root root 64 Apr 24 23:49 6 -> /var/log/nginx/access.log.1

(I'm running this on access.log, in case that's unclear, and logrotate moves the file to access.log.1 on rotation)

I'm thinking that because lograte is moving the file, the inode isn't changing and so it just looks like the file isn't being updated anymore, and dendrite waits for more data which never comes. The kernel knows better, and it shows that the file descriptor is pointing to the moved file...

Also worth noting:

ls -hal access.log.1

-rw-r----- 1 justin adm 3694944 Apr 24 23:46 access.log.1

cat offsets/access.log.ptr

3694944

So, perhaps dendrite thinks that it's seen all the data from that file so far, and is awaiting more?

One more theory: perhaps lograte is moving access.log to access.log.1, and dendrite tries to open access.log before it's been recreated?

Anyway, will read through some code and see if anything looks suspicious there.

-J

[Kyle Maxwell]

I think its because dendrite has a map of tails keyed by original filename.  Dendrite still has access.log.1 open, but thinks it's access.log, and so prevents a new tail being opened on access.log.

[Kyle Maxwell]

This is fixed in master.