monolog-bundle
monolog-bundle copied to clipboard
symfony
Stream handler not closing and causing "too many open files error"
I have come across an issue where when running a significant number of Behat scenarios (260 in my cases) throws a "too many open files error". It looks like this is because the Monolog stream handler is not being closed and as Behat boots a new kernel each time new stream handlers are created (I've checked this using lsof and there are definitely an increasing number of file handles to the log file). I think this is the issue referenced in https://github.com/symfony/symfony/issues/26146
The issue above references a workaround which does work for me too. However the workaround is a bit of a hack. I'm wondering if the bundle itself should take care of this. In normal working mode, it doesn't cause the problem as there is a single kernel instance per request which gets closed and hence the stream handler is closed as the request is closed. Possibly a tag to identify each handler created and then implementing the shutdown() method in MonologBundle to close any handlers it can find. I can create a PR for this if you feel that approach works.
Hello,
I think I miss something here. As soon a the kernel shutdown, the container is cleaned, and all instances are destructed. So the resource should be close.
I agree that's what should be happening but I don't think it is. I don't think anything is explicitly close/destroying the handler so the stream is left open. The Kernel::shutdown() method calls the MonologBundle::shutdown() method but that does nothing. The Kernel::shutdown() sets its container to null but I'm guessing there's a reference to the container somewhere so the actual object(s) aren't being garbage-collected. In "normal" operation, if the objects aren't being GC-ed, they will be when the request ends and so the file handle will be closed then.
Explicitly closing the Monolog handler via
if ($this->container->has('test.service_container')) {
$this->container->get('test.service_container')->get('monolog.handler.main')->close();
}
in our AppKernel::shutdown() method works (as it, we stop getting the error and the count of open log file handles remains pretty constant). But obviously that's a pretty horrible hack. I'm wondering whether the MonologBundle::shutdown() could explicitly close any handlers to tidy up? Is it worth me having a go at a PR for it? Or are there specific reasons why we wouldn't want to do it?
I thing you are right about the GC !
I'm a bit reluctant about the MonologBundle::shutdown(). I think we can do something better here. IMHO a new class "HandlerHolder" whould be easier to implement. But feel free to give a try 👍🏼 I would be happy to merge a PR
What are your concerns about using MonologBundle::shutdown()? Isn't that what it's intended for? How do you see the HandlerHolder working? Is there an issue with race conditions, i.e. close a log handler while other parts of the system might still hold a reference to it and might still want to write log messages?
Bundle are not really in the DIC. I'll be much easier to Create a new service, and to inject all service tagger monolog.handler in it :)
Is there an issue with race conditions, i.e. close a log handler while other parts of the system might still hold a reference to it and might still want to write log messages?
I don't think so in this situation
Ok, so would the new service then listen for kernel shutdown events and close the handlers in response to that event?
Hmmm, looking at it in a bit more detail, it does look like the shutdown() method is the best place for this. The Behat extensions explicitly shuts down the kernel: https://github.com/FriendsOfBehat/SymfonyExtension/blob/master/src/Listener/KernelOrchestrator.php#L46 and the kernel shutdown calls any bundle shutdown methods. My concern with listening to a terminate event is that we would need to make sure anything using the logger has been terminated already, which could be difficult.
The other way would be to force the gc_collect_cycle() in behat extension (I don't know behat, so I could not really help here)
Possibly it could be done in Behat (or rather the Behat-Symfony extension) but IMHO components that create/open resources should be responsible for destroying/closing them correctly. It feels like a bit of a sledgehammer for the Behat extension to have to force a GC cycle to clear up after other services (but then I'm not experienced in the Symfony internals, perhaps the Kernel was only ever intended to be used once in a single request and Behat is diverging from that?)
Actually, Monolog already clean everything:
- https://github.com/Seldaek/monolog/blob/master/src/Monolog/Handler/StreamHandler.php#L62-L69
- https://github.com/Seldaek/monolog/blob/39637a5d0e98068d98189ce48a87f3dd61455429/src/Monolog/Handler/Handler.php#L38-L45
I think that's why it works in "normal" (i.e. single kernel per request) circumstances but don't think the __destruct is getting called in the Behat scenario. Looking at the Behat extension it does look like it is handling the kernel as expected (i.e. by calling $kernel->shutdown() in the test tearDown() method.
When the $kuernel->shutdown() is called, the handler object could still be referenced or the garbage collector simply has not triggered perhaps. In this situation, the __destruct is not getting called.
https://www.php.net/manual/en/language.oop5.decon.php#language.oop5.decon.destructor
This is a demo of the issue. It was created using plain phpunit with Symfony to rule out the potential impacts by the Behat integration.
https://github.com/torreytsui/symfony-too-many-open-files-replication
Just dug a bit and found that Doctrine had the same issue with the database connection resources.
They seem to have handled it in the bundle shutdown
https://github.com/doctrine/DoctrineBundle/blob/132e3c14bfafc7ffaf9e3781c0ed87df609562cf/DoctrineBundle.php#L127-L138
Not sure if this is a good practice, but would be a good reference.
More details on the Doctrine's issue thread.
https://github.com/doctrine/DoctrineBundle/pull/366#issuecomment-69341472
The reasoning on the approach does make sense to me. What do you think?
it would make sense to me to iterate over (instantiated) handlers in MonologBundle::shutdown and close them, indeed.
