Stream handler not closing and causing "too many open files error"

[andy-educake]

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 symfony/symfony#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.

[lyrixx]

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.

[andy-educake]

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?

[lyrixx]

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

[andy-educake]

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?

[lyrixx]

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

[andy-educake]

Ok, so would the new service then listen for kernel shutdown events and close the handlers in response to that event?

[andy-educake]

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.

[lyrixx]

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)

[andy-educake]

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?)

[lyrixx]

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

[andy-educake]

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.

[torreytsui]

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

[torreytsui]

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.

[torreytsui]

More details on the Doctrine's issue thread.

doctrine/DoctrineBundle#366 (comment)

The reasoning on the approach does make sense to me. What do you think?

[stof]

it would make sense to me to iterate over (instantiated) handlers in MonologBundle::shutdown and close them, indeed.