linemux

linemux copied to clipboard

Hi, I'm trying to collect logs from Apache access log files, but I stop receiving lines every time the log files rotate.

For a test, I have Apache configured to rotate logs every 30 seconds:

CustomLog "|/usr/bin/rotatelogs -l -f -D -n 10 -L ${APACHE_LOG_DIR}/latest.access.log ${APACHE_LOG_DIR}/rotated.access.log 30" common

According to rotatelogs documentation, this makes latest.access.log a hard link that always has the latest version of the logs. If I follow it using tail, it works:

$ tail -F /var/log/apache2/latest.access.log

[12/Sep/2022:00:25:25 +0000] 172.23.0.1 "GET / HTTP/1.1" 403 493 0
[12/Sep/2022:00:25:25 +0000] 172.23.0.1 "GET /favicon.ico HTTP/1.1" 404 489 0
[12/Sep/2022:00:25:29 +0000] 172.23.0.1 "GET / HTTP/1.1" 403 493 0
tail: '/var/log/apache2/latest.access.log' has been replaced;  following new file
[12/Sep/2022:00:25:31 +0000] 172.23.0.1 "GET / HTTP/1.1" 403 492 0

If I use MuxedLines::add_file on the same file, I stop receiving lines once the file is rotated:

Found log file: /var/log/apache2/latest.access.log
[LogWatcher] Watching 1 log file(s).
[LogWatcher] Received line: [12/Sep/2022:00:26:57 +0000] 172.23.0.1 "GET / HTTP/1.1" 403 493 0
[LogWatcher] Received line: [12/Sep/2022:00:26:57 +0000] 172.23.0.1 "GET /favicon.ico HTTP/1.1" 404 489 0

Thanks for the report, I'll take a look. Would you be able to get a strace log of what rotatelog is doing during that rotation? That would inform of what hooks linemux is missing.

Slightly different names, third.error.log is the hard link to latest and rotated/third.error.log.X is the rotated file.

strace: Process 23 attached
read(0, "[Tue Sep 13 20:04:10.499934 2022"..., 65536) = 260
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fc089531000
mkdir("/var/log/apache2/rotated", 0777) = -1 EEXIST (File exists)
openat(AT_FDCWD, "/var/log/apache2/rotated/third.error.log.1", O_WRONLY|O_CREAT|O_TRUNC|O_APPEND|O_CLOEXEC, 0666) = 4
unlink("/var/log/apache2/third.error.log") = 0
link("/var/log/apache2/rotated/third.error.log.1", "/var/log/apache2/third.error.log") = 0
close(3)                                = 0
write(4, "[Tue Sep 13 20:04:10.499934 2022"..., 260) = 260
read(0,

Hi, do you have any ideas about why it's not working?

Still hoping to get a better handle on the link semantics and the notify crate, but I was able to repro, and it looks like there should be a path to a fix. On every file rotation, notify emits a Modify(Metadata(Any)) event which corresponds to a change in the underlying inode.

Pushing random lines to file /tmp/foo.log:

jon@r4 ~/src/oss/httpd/download/httpd-2.4.54/support $ ./rotatelogs -v -l -f -D -n 10 -L /tmp/foo.log /tmp/rotated.foo.log 30
Rotation time interval:                30
Rotation size interval:                 0
Rotation time UTC offset:               0
Rotation based on localtime:          yes
Rotation file date pattern:            no
Rotation file forced open:            yes
Create parent directories:            yes
Rotation verbose:                     yes
Rotation create empty logs:            no
Rotation file name:  /tmp/rotated.foo.log
Post-rotation prog:              not used
Creating directory tree /tmp
Opening file /tmp/rotated.foo.log
Linking /tmp/rotated.foo.log to /tmp/foo.log
asdf
zxcv
qwer
erty
xcvb
erty
File rotation needed, reason: Time interval expired
Creating directory tree /tmp
Opening file /tmp/rotated.foo.log.1
Linking /tmp/rotated.foo.log.1 to /tmp/foo.log
Closing file /tmp/rotated.foo.log

Results in (with some extra debugging):

jon@r4 ~/src/jmagnuson/linemux $ target/debug/examples/lines /tmp/foo.log
event: Event { kind: Create(File), paths: ["/tmp/foo.log"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
ino: 12320771
event: Event { kind: Modify(Data(Any)), paths: ["/tmp/foo.log"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
ino: 12320771
(/tmp/foo.log) asdf
...
event: Event { kind: Modify(Data(Any)), paths: ["/tmp/foo.log"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
ino: 12320771
(/tmp/foo.log) xcvb
event: Event { kind: Modify(Metadata(Any)), paths: ["/tmp/foo.log"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
ino: 12320772
event: Event { kind: Access(Close(Write)), paths: ["/tmp/foo.log"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
ino: 12320772

It should be possible to hook that into some re-watch logic to update both the stored File handle, as well as the watch itself in notify::Watcher since the same issue exists upstream (e.g. async_monitor).

I reimplemented the tailing logic in my project to see how far I can get, and found that besides Modify(Metadata(Any)) you mentioned, watching the parent folder also fired a Remove(File) and Create(File) event with the path to the file.

This seems to be more reliable in case that a file is quickly rotated twice, because the watcher on the parent folder gets notified of every rotation, but if you only watch the file itself for metadata changes, there's a race condition where you lose the second rotation because it happens before you've re-watched the file after the first rotation.

While this should be unlikely, when I started a container with Apache and my program at the same time, for some reason Apache did a double rotation of all log files during its initialization, so my program lost events.

Right now, my program keeps a Lines reader for a file until it gets a Create(File) event, at which point it reads remaining lines in the old file which Linux keeps alive until all handles are closed, and then it opens the new file and starts reading from the beginning. I don't think my solution would work on Windows because it would prevent the file from being deleted (and perhaps even written to by Apache), but maybe some of what I said could be helpful.