Sometimes Monolog logs incorrectly inside of a thread

[angstymeat]

If you know how to write phpt tests, please open a PR with environment information, and your test, this will cause CI to test your issue before a human is able to look

Environment

• PHP:

PHP 7.2.14 (cli) (built: Jan  8 2019 14:11:13) ( ZTS )
Copyright (c) 1997-2018 The PHP Group
Zend Engine v3.2.0, Copyright (c) 1998-2018 Zend Technologies
    with Zend OPcache v7.2.14, Copyright (c) 1999-2018, by Zend Technologies

• pthreads: Version => 3.2.1dev I've compiled pthreads myself from the git master copy as of January 26 (8f4205d)

• OS: Linux xxxxxx 3.10.0-957.1.3.el7.x86_64 #1 SMP Thu Nov 29 14:49:43 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux

Summary

I don't know if this is a pthreads issue, a Monolog issue, or something else.

I have written software which starts multiple threads to handle and parse emails as they arrive and save the results to a database. I log program flow with Monolog writing to syslog. Every now and then (at least several times per day) I see a log entry written without the correct syslog program name. This causes the entry to be owned by zts-php and gets written to my php log instead of the application's log.

I have tried a number of code changes over the last year and the problem still persists. For a while I thought it was a race condition with some of the variables I was using being destroyed before Monlog was finished logging. However, I now initialize Monolog completely inside of run(), and have hard-coded the Monolog channel name for debug purposes, and I still have incorrect entries.

I am using syslog-ng as my syslog.

Reproducing Code

The example below should log using the name "test".

This runs 200 simultaneous threads 20 times to illustrate the problem. My actual application only runs 8 at most, handling up to 100 messages each, but this sample will always trigger the issue on my server. It seems to be related to the number of threads and the amount of logging in each thread.

This code is simpler than my actual running code. My real code also uses a pthreads' synchronize/wait before each thread exits to record statistics back to the parent. I have a few log lines after synchronized() is called, and I have noticed in this case the erroneous entries are always the ones written after synchronized() is finished.

<?php

use Monolog\Logger;
use Monolog\Formatter\LineFormatter;
use Monolog\Handler\SyslogHandler;

class LogTest extends \Thread
{

    protected $name;

    public function __construct()
    {
        $this->name = substr(md5(microtime(true) . rand()), 0, 10);
    }

    public function setName(string $name)
    {
        $this->name = $name;
    }

    protected function newLogger()
    {
        $logger = new Logger('test');

        $handler = new SyslogHandler("test", LOG_USER);
        $handler->setFormatter(new LineFormatter("%message%"));
        $logger->pushHandler($handler);

        return $logger;
    }

    public function run()
    {
        require_once '../vendor/autoload.php';

        $logger = $this->newLogger();
        $this->logger = $logger;

        $logger->log(Logger::INFO, "$this->name: Thread Starting.");
        for ($i = 0; $i < 100; $i++) {
            $logger->log(Logger::INFO, "$this->name: Loop $i (do work)");
            usleep(rand(0, 30) * 1000);
            $logger->log(Logger::INFO, "$this->name: Loop $i (finish work)");
        }

        $logger->log(Logger::INFO, "$this->name: Done");
    }
}

$x = [];
// Run 200 threads 20 times.
for ($j = 0; $j < 20; $j++) {
    for ($i = 0; $i < 200; $i++) {
        $x[$i] = new LogTest();
        $x[$i]->start(PTHREADS_INHERIT_NONE);
    }
}

Expected Output

A bunch of entries get written to application.log along the lines of :

Jan 31 16:00:44 xxxxxxx test[5811]: 7f23b3a7cf: Loop 97 (finish work)
Jan 31 16:00:44 xxxxxxx test[5811]: 7f23b3a7cf: Loop 98 (do work)
Jan 31 16:00:44 xxxxxxx test[5811]: 19a1c37fab: Loop 98 (finish work)
Jan 31 16:00:44 xxxxxxx test[5811]: 19a1c37fab: Loop 99 (do work)
Jan 31 16:00:44 xxxxxxx test[5811]: 7f23b3a7cf: Loop 98 (finish work)
Jan 31 16:00:44 xxxxxxx test[5811]: 7f23b3a7cf: Loop 99 (do work)
Jan 31 16:00:44 xxxxxxx test[5811]: 19a1c37fab: Loop 99 (finish work)
Jan 31 16:00:44 xxxxxxx test[5811]: 19a1c37fab: Done
Jan 31 16:00:44 xxxxxxx test[5811]: 7f23b3a7cf: Loop 99 (finish work)
Jan 31 16:00:44 xxxxxxx test[5811]: 7f23b3a7cf: Done

Actual Output

Entries are written to the application.log, but some get written to my php log file:

Jan 31 16:00:36 xxxxxxx zts-php[5811]: cdd65ac191: Loop 69 (finish work)
Jan 31 16:00:41 xxxxxxx zts-php[5811]: 87a58b2f0a: Loop 70 (finish work)
Jan 31 16:00:42 xxxxxxx zts-php[5811]: 5760e6f93d: Loop 9 (finish work)
Jan 31 16:00:43 xxxxxxx zts-php[5811]: 69d9ccd7f4: Loop 67 (finish work)

[joeyhub]

It might be worth checking it with strace. It's possible monolog might be trying flock on the application log then falling back if it fails to get a lock in time.

Using libs with IO could be especially likely to have some issues.

The issue is sysloghandler isn't thread safe. It has openlog,syslog,closelog.

That means execution can be open,open,log,close,log,close.

You should always be very careful using libs with pthreads especially ones with IO.

You should have monolog wrapped in a thread as a singleton. I'm not sure how interthreads coms works here but customarily you'd want a queue or mutex (mutex can work without the singleton).

Syslog doesn't look thread safe. Note that also having lots of monolog instances isn't necessarily great on resources.

[angstymeat]

Thanks for the reply! Just wanted to let you know that I had read your response, but hadn't had a chance to try it out since I was working on another project until now.

I hadn't thought about this solution, but it makes sense. I implemented it today by creating a new Threaded class that implements the logging and then passing that as a parameter to the threads. The log writing function uses synchronized(). It appears to be working in my project as well as a modified version of my test case, above.

My real project doesn't have as many Monolog instances as the test case above generates; this was just to make it happen faster. However, this should still reduce the resources.

My reading indicates that syslog should be thread-safe, but isn't implemented consistently.

Thanks for pointing me in the right direction!