How come log lines written by Monolog don't get messed/mixed up when two script instances are writing to log concurrently?

Question

When using Monolog with StreamHandler, it is normal situation that several instances of PHP script would be writing to the same log file in parallel.

(eg. in my Symfony application, when mulitple users open "Login page" at the same time, it would result in multiple instances of my app script (app.php) running and thus two instances of Monolog StreamHandler would be writing into same app/logs/prod.log.)

How come that despite of concurrent writing to the file, each log lines is not broken in the middle and messed up? How come the situation below never happens:

instance1 of StreamHanler only wrote half of the log line,
instance2 of StreamHanler wrote it's first half
instance1 wrote second half of the log line
instance2 wrote second half of the log line
now our log file is a mess, because two lines are mixed.

I tried looking at the source code of the StreamHanler https://github.com/Seldaek/monolog/blob/master/src/Monolog/Handler/StreamHandler.php#L93

But I do not see any proper concurrency control, there is a flock() but it seems to be disabled (->useLocking=false) in default (Symfony) configuration and it seems that logs are fine without it...

    if ($this->useLocking) {
        // ignoring errors here, there's not much we can do about them
        flock($this->stream, LOCK_EX);
    }
    fwrite($this->stream, (string) $record['formatted']);
    if ($this->useLocking) {
        flock($this->stream, LOCK_UN);
    }

But why are the logs magically fine?

@Progrock i didn't, but my understanding is that fwrites() are writing to OS file-buffer (cache) which is flushed by OS. So even if multiple processes do fwrite() on the same file each fwrite() ATOMically writes to OS cache and entire log line will be written in whole. Then OS flushes it's buffer (made of complete log lines). And OS buffer always contains full lines and flushing to disk would be a guaranteed. When log lines written eg. word by word with multiple fwrites() only then they will get mangled. Not even very long lines (larger than OS buffer) can cause manging (unless HDD failure) — Dimitry K
Seems like the behaviour i described above only holds if file is open in APPEND mode stackoverflow.com/a/35258623/1168382 — Dimitry K

Aitch Aitch · Accepted Answer · 2015-03-27T15:11:30

When I use logging I would expect the underlying components to work correct. It's not any container you have to ensure concurrency access.

I've read, that the main stream operating systems use thread-safe io calls which are also not interruptable and there are non thread safe calls.

You can read here, but in my opinion the marked answer is not correct at all: Is fwrite atomic?

In other words I've never had any broken logs. It's like INSERT in a database. Either there is a row inserted or not.

How come log lines written by Monolog don't get messed/mixed up when two script instances are writing to log concurrently?

1 Answers