Buffered Nginx log reading using PHP and logrotate

The problem: We want to continuously read the Nginx access logs on our high-traffic web nodes for real-time analytic purposes.

Logrotate every 10 seconds

Not possible! The minimum that logrotate allows is hourly. Apart from that I do not think this is very practical. I would still prefer to keep the logfiles hourly, for easy disk management. I do not like an hour of delay on my statistics. I would prefer something like one minute until it reaches the MySQL database.

Using a named pipe with mkfifo

The idea is that you can make a pipe with “mkfifo” and configure Nginx to log to that file. Sounds good until you realize that the buffer size of the pipe is quite limited (a few kb) and it will just silently drop log lines on buffer overflow. Also Igor Sysoev advised that you should not do it and since he knows what he is talking about, I suggest you stay away from it. 🙂

Watch the log file with inotify

This idea is to install a watcher on the log file that triggers an event when the file is written to. This is a good idea, but the amount of events on a busy server may be just a little too high for this to be really efficient. We would rather not be notified every time the filesystem sees a change on the Nginx access log file. EDIT: This is actually not a bad idea as long as you enable buffered Nginx access logging, see next post.

Open the file and read until EOF every x seconds

Open the file and keep it open. Sleep for x seconds and read the file until the end. Send that data to your statistics cluster and return to the sleep. This works great until the file gets rotated. Once the file gets rotated, you first need to finish reading the old file until you start reading the new one. Fortunately, logrotate moves the file by default and a open moved file can still be read using the original file descriptor. When we find that that the file has been moved y seconds ago and not been written to for z seconds, then we can decide to close the rotated file and open the new current file. This way we can ensure that we do not lose any log lines. Certainly x, y, and z need some values found using trial and error. I think five, three, and one seconds should be a good starting point.

Configure logrotate to rotate hourly for 48 hours

This can be done using the following logrotate script:

/var/log/nginx/*.log {
        hourly
        missingok
        rotate 48
        compress
        delaycompress
        notifempty
        create 0640 www-data adm
        sharedscripts
        prerotate
                if [ -d /etc/logrotate.d/httpd-prerotate ]; then \
                        run-parts /etc/logrotate.d/httpd-prerotate; \
                fi \
        endscript
        postrotate
                [ -s /run/nginx.pid ] && kill -USR1 `cat /run/nginx.pid`
        endscript
}

Make sure you also move the logrotate cron job from daily to hourly using:

sudo mv /etc/cron.daily/logrotate /etc/cron.hourly/logrotate

Read the log files

The following code is an example in PHP that will demonstrate how this log reader will work. Note that Python and Golang may be more suitable languages for implementing these kinds of long running programs. This script just prints the data it reads. Streaming the log lines to your big data analytics cluster is left as an exercise to the reader. 😉

<?php
$logfile = "/var/log/nginx/access.log";
$var_x = 5;
$var_y = 3;
$var_z = 1;
$f = fopen($logfile, "r");
fseek($f,0,SEEK_END);
while (true) {
  $data = stream_get_contents($f);
  echo $data; // or send the data somewhere
  clearstatcache();
  $s1 = fstat($f);
  $s2 = stat($logfile);
  $renamed  = $s1["dev"] != $s2["dev"] || $s1["ino"] != $s2["ino"];
  if ($renamed && time()-$s1["ctime"]>$var_y && time()-$s1["mtime"]>$var_z) {
    echo "renamed\n";
    while (!file_exists($logfile)) sleep(1);
    fclose($f);
    $f = fopen($logfile,"r");
  } else sleep($var_x);
}
fclose($f);

While running the script above you can make sure the access log is written to another terminal using:

siege -c 100 http://localhost/

Now you can force the rotation to be executed using:

sudo logrotate -f /etc/logrotate.d/nginx

And see how the script gracefully handles it.

6 thoughts on “Buffered Nginx log reading using PHP and logrotate”

  1. 1) “The sleep() function shall cause the calling thread to be suspended from execution until either the number of realtime seconds specified by the argument seconds has elapsed or a signal is delivered to the calling thread and its action is to invoke a signal-catching function or to terminate the process. The suspension time may be longer than requested due to the scheduling of other activity by the system.”
    So you never know how long it will take to wake up, specially on busy systems (The ones you say inotify is not good)

    2) Getting file access times is not guaranteed to work on all filesystems

    3) time() calls are not that cheap

    4) Inotify is a kernel event, a few bytes in syze and it also has mechanisms to warn the app in case of errors
    4.1) Your approach has none.

    5) I’m almost sure that most of the operations you use (fstat, stat, file_exists) cause I/O, Inotify causes none.

    Conclusion:

    You try to mimic a behavior that is built in the Linux kernel and you do it badly. That’s why we use Inotify @the CDN team.

  2. @Carlos: Thank you for your comments. Let me try to reply to each of the points:

    1) Inotify event handlers also run in user space and depend on being scheduled (see 4).

    2) It is not doing that, only the modified and creation times are read.

    3) Relative measure, but twice per 5 seconds is not very often either, right?

    4) To get events, an application does a blocking read on the inotify FD (see 1).

    4.1) Because this is proof-of-concept code to explain the algorithm.

    5) Ok, but this is getting scheduled less often and thus leads to lower CPU use.

    source: http://linux.die.net/man/7/inotify

  3. 1) Both depends on signals, so the same
    2) With Inotify I don’t need this anyway 🙂
    3) Again, not needed with Inotify
    4) Is not a problem, I actually only need to perform work when Inotify notifies my app
    5) Since when less schedule means lower CPU? Less schedule means context switching. Spinlocks also avoid context switching and I don’t see them as a good practice. But let’s see this less CPU usage in detail:

    Case a)
    wait for Inotify
    process_data() // Only used when data is present

    Case b)
    wait for sleep()
    process_data() // Could be the case no data is present
    fstat()
    stat()
    time() + comparison
    time() + comparison

    Case b) wastes CPU cycles even when no data is available, case a) no. This doesn’t lead to lower CPU usage…
    Every time data is present your algorithm does 4 more calls (2 of them I/O related), this also doesn’t lead to lower CPU usage.

    I also don’t see a proper explanation about “may be just a little too high for this to be really efficient”. And my analysis show that your algorithm will actually cause more load that the one needed, thus worsening the case for a loaded machine.

    If you can get this sorted maybe I can try your algorithm (Show error handling also, since in Inotify that is trivial).

  4. @Carlos: Thank you. I’ll argue why it might be “a little too high” in my next post about context switching.

  5. @Gregory: Thank you for your comment. Interesting suggestion. I have no idea and I would have to try that, but it sounds promising.

Leave a Reply

Your email address will not be published. Required fields are marked *