After BufferHandler::close(), ignore further close() calls

[tstarling]

BufferHandler overrides the parent destructor, but it's possible for close() to be called from a destructor anyway, late during request shutdown, if the BufferHandler is put in a GroupHandler.

So, avoid flushing the logs twice by ignoring the second call to close().

Downstream bug https://phabricator.wikimedia.org/T288624

[Seldaek]

Interesting issue.. But if flush() triggers an issue it means something was logged between close() and destruct. Otherwise flush would have nothing to flush and it'd be a noop. So that sounds a bit concerning to me, and IMO should be investigated on your end?

The other weirdness is that in destruct we do catch exceptions coming from close(), so in theory this should not error? I'm not sure where the error comes from? I guess it might be because it is a warning and not an exception. Perhaps the more appropriate fix here would be to register a temporary noop error handler in Handler::destruct?

I am digging in here because I don't like the proposed fix as it makes the handler unusable after close is called, and ideally handlers should keep functioning/reopen if logs arrive after close.

[tstarling]

Interesting issue.. But if flush() triggers an issue it means something was logged between close() and destruct. Otherwise flush would have nothing to flush and it'd be a noop. So that sounds a bit concerning to me, and IMO should be investigated on your end?

Probably. It's a big application, with a lot of developers, I don't think we can enforce this as a policy. Maybe we can call close() a bit later. But the destructor is too late -- the bug shows that you can't expect flush to work reliably during zend_objects_store_call_destructors(). Objects are destroyed in a random order so you can't safely call any method or use any property of an object other than $this.

The other weirdness is that in destruct we do catch exceptions coming from close(), so in theory this should not error? I'm not sure where the error comes from? I guess it might be because it is a warning and not an exception. Perhaps the more appropriate fix here would be to register a temporary noop error handler in Handler::destruct?

Yes it's a warning.

Trying to ignore all the weird and broken things that are going on during request shutdown is not a very satisfying solution. If an app really was relying on flush() being called from __destruct(), those warnings would be the only indication they have that some or all of their log events are being thrown away.

I don't mind throwing away log events from very late in request shutdown, but we're buffering events, so there's a risk of losing the whole buffer.

I am digging in here because I don't like the proposed fix as it makes the handler unusable after close is called, and ideally handlers should keep functioning/reopen if logs arrive after close.

I see that it contradicts the HandlerInterface::close() doc comment which says that handlers should reopen after close. So feel free to close this PR.

An alternative might be to add a method which causes the handler to temporarily ignore log events. Maybe something like

interface HaltableInterface {
    function halt();
    function resume();
}

[Seldaek]

Yeah I'm sorry but I don't quite see what can be done here without potentially causing more problems for others so I think I'll have to close.