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.