How do I retry a PHP flock() for a period of time?

Question

I need to open a log file for writing. Trouble is, many things may do this at the same time, and I don't want conflicts. Each write will be a single line, generally about 150 bytes (and always less than 1K), and getting things in chronological order is not strictly required.

I think what I want is to attempt to flock(), and if it fails, keep trying for a few seconds. If a lock can't be established after a number of tries, then give up.

$fh=fopen($logfile, "a");

if (flock($fh, LOCK_EX|LOCK_NB)) {
  $locked=TRUE;
} else {
  $locked=FALSE;
  // Retry lock every 0.1 seconds for 3 seconds...
  $x=0; while($x++ < 30) {
    usleep(100000);
    if (flock($fh, LOCK_EX|LOCK_NB)) {
      $locked=TRUE;
      break;
    }
  }
}

if ($locked) {
  if (fwrite($fh, strftime("[%Y-%m-%d %T] ") . $logdata . "\n")) {
    print "Success.\n";
  } else {
    print "Fail.\n";
  }
  flock($fh, LOCK_UN)
} else {
  print "Lock failed.\n";
}

I have two questions, one general and one specific. First, aside from implementing the same solution in different ways (do...while, etc), is there a better general strategy for handling this kind of problem, that runs solely in PHP? Second, is there a better way of implementing this in PHP? (Yes, I separated these because I'm really interested in the strategy part.)

One alternative I've considered is to use syslog(), but the PHP code may need to run on platforms where system-level administration (i.e. adding things to /etc/syslog.conf) may not be available as an option.

UPDATE: added |LOCK_NB to the code above, per randy's suggestion.

Moskowitz

Is the file being accessed by other processes independent of PHP/the webserver? Are there any other scripts that will have concurrent access to it? – Appealing

@DeaconDesperado: Generally, PHP will be all that writes to the files. I expect log aging (renaming files) will happen at some point in the future, but I don't think I need to plan for that just yet. I expect the file will be opened for reading by various tools including less, tail -f and awk. – Moskowitz

I personally like/would use your approach in a PHP context if what we're talking about is just logs. If there were larger requirements and the concurrency in question was business logic I'd suggest looking into a message queue... something like RabbitMQ/Beanstalkd. I've done similar logging using MongoDB/Python as a queue for these kinds of messages. These kinds of queues are designed to attempt the job again in the event of failure. – Appealing

+1 for what @DeaconDesperado said about MQs. Also, if this is just logging, I would think that file_put_contents('/path/to/log', $content, FILE_APPEND|LOCK_EX) would suffice – Bufordbug

@randy: so you're suggesting I could just repeat that command until either it's successful or 3 seconds have elapsed? – Moskowitz

I suppose you could... How frequently are you writing to the log? Are you sure there would be collisions? If you're writing a lot of data in rapid succession, then file_put_contents will slow you down since it has to open the file, acquire the lock, write the data and close the file. See this comment. If you need speed, then using a message queue is the way to go as it's non-blocking (fire and forget). Otherwise, either scenario should work. – Bufordbug

Also, be careful with locking. If your PHP process dies in the middle of a lock, it's possible that lock may still exist the next time you try to lock it. Read up on flock and blocking. "By default, this function will block until the requested lock is acquired; this may be controlled (on non-Windows platforms) with the LOCK_NB option documented below." – Bufordbug

ghoti, I think what you really want to do is redefine your specifications so that you can include either a message queue in front of the log, or insist on syslog being available. – Sinful

@randy, the logging would happen in quick bursts of single lines from a client application that will always be running simultaneously on a few client computers. It is likely that multiple requests from different clients could arrive on the server very close to each other. If file_put_contents takes care of the fopen/flock/fwrite/fclose, what else do you suppose it's doing that would account for the extra overhead? I don't really need speed (as I'm willing to wait 3 seconds for a lock to be set), but I'd rather not corrupt or lose log entries. – Moskowitz

@randy, thanks for your suggestion. I've updated the question with LOCK_NB. It sounds as if while in an ideal world, flock() should work. If the risks are just usage gotchas, I'm okay with that. I'll explore MQ, but my first thought was that I don't like the idea of the client not knowing whether its logging attempt was successful. – Moskowitz

It seems that using LOCK_NB and usleep would negate each other. i.e. file_get_contents will block by default which means it will block other calls in the stack until it can obtain an exclusive lock on the file for writing. If file_get_contents returns FALSE after that, it most likely won't be because it couldn't obtain the lock... if that makes sense? This is all speculation from reading the docs. I don't have any examples or definitive proof that it would behave like this in the Real World – Bufordbug

The overhead comes from the open/lock/write/close. If you were to write a logger that kept an open file handle, it would be faster (open/lock/write/write/write/close). The link I sent is a bit of an edge case... you probably won't be logging 10k messages in one request (will you?). If they're single messages per/request, there's not much you can do to maintain an open file handle between requests... short of writing a daemon that listens for messages and logs them. Long story short; I wouldn't worry about the extra overhead between the two implementations. – Bufordbug

The log lines are single lines of text, usually in the range of 150 bytes, very rarely exceeding 600 bytes. My read of the docs is that file_get_contents doesn't support LOCK_NB, so it seems it would block indefinitely. Which is makes timing out hard. It would return FALSE if it couldn't open the file for write. So ... I prefer the manual fopen/flock/fwrite/fclose combo over file_put_contents because it provides me with more granular control over the process. I totally agree that a daemon would be the way to go (even syslog), but I can't guarantee access to one. – Moskowitz

you really should sleep AFTER flock fails, not before. by sleeping before flock, you make sure the code always sleep, even when there's no need to sleep – Coliseum

@hanshenrik, it is running the sleep after a lock failure, the one on the if() line. – Moskowitz

Answer 1

In my long experience in PHP making logs (under linux!) I've never experienced problems of conflicts (even with hundreds of simultaneus and concurrent writes). So simple skip lock maagement:

$fh=fopen($logfile, "a");
if (fwrite($fh, strftime("[%Y-%m-%d %T] ") . $logdata . "\n")) {
    print "Success.\n";
  } else {
    print "Fail.\n";
  }
fclose($fh);

About this strategy the file logging (with or without lock) is not the best solution, because every fopen with the "a" imply a seek syscall to set the cursor at the end of the file. syslog keeping the file open avoid this overhead.

Of course the overhead become significative (in performance) with "big" files, an easy solution is create log file with date (or date-time) in the name.

ADD

apache package include a tester program: ab, allowing doing query in concurrency, you can test my thesis stressing your server with 1000000 of query done by 10to1000 threads.

ADD - following the comment

No, it'not an impossible task.

I found a note from http://php.net/manual/en/function.fwrite.php

If handle was fopen()ed in append mode, fwrite()s are atomic (unless the size of string exceeds the filesystem's block size, on some platforms, and as long as the file is on a local filesystem). That is, there is no need to flock() a resource before calling fwrite(); all of the data will be written without interruption.

to know how big is a block in bytes (usual 4k):

dumpe2fs /dev/sd_your_disk_partition |less -i

The "atomicity" of write is realized blocking other "agents" to write (when you see process in "D" status in "ps ax"), BUT PHP stream facility can solve this problem, see: *stream_set_blocking*. This approach can introduce partial writes, so you will have to validate the integrity of your records.

In any case a fwrite (network or file) is susceptible to block/failure regardless of use of flock. IMHO flock introduce only overhead.

About your original questions AND your goal (trying to implement corporate policy in a highly risk-averse environment), where even a fwrite can be problematic, I can only imagine a simple solution: use a DB

• most of complexity is out of PHP and written in C!
• total control of the flow of the operation
• hi level of concurrency

Synaesthesia

Alas, I can afford a 2 or 3 second delay for writes, but I can't afford the possibility of corrupt log lines. Either I get a proper log entry, or I report a failure then handle things accordingly. – Moskowitz

As I already said, I write tons of log without one single line corruption. I think that under linux the write(2) is atomic. Of course 1 line per write! – Synaesthesia

If write() is atomic, then it either locks or blocks while the write is occurring. If it locks, then there's the risk that other writes may fail. If it blocks, then other writes could wait indefinitely for the chance to write. Both of those are risks, however remote, that I'm trying to work around. This isn't a question of programming something that will "probably" work, I'm trying to implement corporate policy in a highly risk-averse environment. If this task is impossible, that's another matter, but I don't think that's the case. – Moskowitz

That "note" sounds extremely promising. Thanks for finding that. While I'm not sure whether "atomic" means that a collision is impossible, causes a failure or a delay. If it's a delay, I'm stuck, but I can program around my 3-second requirement for failures and assume the lack of a timeout value on fwrite() means that delays are not an issue. Thanks, this gets you a checkmark. :-) – Moskowitz

Answer 2

here is my implementation of flockWithTimeout, recently posted at https://CodeReview.stackexchange.com/questions/283930/php-flock-with-timeout-for-lock-sh-lock-ex

function flockWithTimeout($handle, int $flags, int &$would_block = null, float $timeout_seconds = 10, float $sleep_time_seconds = 0.01): bool
{
    if($flags !== LOCK_UN) {
        $flags = $flags | LOCK_NB;
    }
    $would_block = null;
    $timeout_timestamp = microtime(true) + $timeout_seconds;
    $sleep_time_microseconds = (int)($sleep_time_seconds * 1000000);
    for (;;) {
        $success = flock($handle, $flags, $would_block);
        if ($success) {
            return true;
        }
        if (!$would_block) {
            // something else is wrong, like flocking on FAT32 which doesn't support flock?
            return false;
        }
        // another process has the lock
        if (microtime(true) >= $timeout_timestamp) {
            return false;
        }
        usleep($sleep_time_microseconds);
    }
    throw new \LogicException('unreachable');
}

sample usage:

$h = tmpfile();
$h2 = fopen(stream_get_meta_data($h)['uri'], "rb");
if(flockWithTimeout($h, LOCK_EX)){
    echo "got the lock! :)\n";
} else {
    echo "did not get the lock :(\n";
}
$timeout_seconds = 0.1;
if(flockWithTimeout($h2, LOCK_SH, $would_block, $timeout_seconds)){
    echo "got the lock! :)\n";
} else {
    echo "did not get the lock :(\n";
}

should print

got the lock! :)
did not get the lock :(

with the did not get the lock :( taking roughly 100 milliseconds

Coliseum