Closed dave-redfern closed 2 years ago
the syslog connection can be terminated before the DBAL middleware drops out of scope
This is a bit unclear. Why is the connection to the remote source terminated while the logger references it? AFAIK, this may happen if there are circular references between objects, so the correct order of their destruction doesn't exist by definition. But it shouldn't happen normally.
As usual, please try to document the steps to reproduce this issue with a minimal set of dependencies (i.e. without using Symfony).
I guess this is the minimum very contrived reproducer:
<?php declare(strict_types=1);
use Doctrine\DBAL\DriverManager;
use Doctrine\DBAL\Logging\Connection;
use Monolog\Handler\SyslogUdpHandler;
use Monolog\Logger;
require_once 'vendor/autoload.php';
$conn = DriverManager::getConnection(['url' => 'sqlite:///memory']);
$logger = new Logger('logger', [
new SyslogUdpHandler('syslog', 514),
]);
$conn = new Connection($conn->getWrappedConnection(), $logger);
$conn->query('SELECT * FROM sqlite_schema');
$logger->close();
I've tracked it back specifically to the interaction of monolog/bridge
and the ConsoleHandler
that subscribes to ConsoleEvent::TERMINATE
where it calls ->close()
on all open handlers. That happens within SF Console\Application::doRunCommand
after the command execution. So __destruct on the DBAL Logger\Connection is only called after that and then it errors since all logger handlers have been closed.
So far, it looks like the problem is in the ConsoleHandler
rather than in the logging middleware. If it wants to close the logger explicitly (which makes quite little sense to me given PHP's shared-nothing architecture), it should close the connection as well, before closing the logger.
Unfortunately I can't say. Perhaps there is a reason for explicitly closing log handlers on the CLI? That would be a question for the maintainers of monolog-bridge though.
All I can offer is that it's unwise to rely on consistent behaviour of an externally configured service during object destruction.
Unless this issue is fixed outside of the DBAL, the only solution I can think of is to remove logging from the destructor. I agree that strictly speaking, the destructor should only do the cleanup and should not rely on the other resources being available.
Linking https://github.com/symfony/symfony/pull/8167 for reference.
Strictly speaking, the PSR-3 standard does not say anything about "closed" loggers. It should more or less always be safe to write to a logger, if one is present. The standard does not define any errors (apart from exceptions because of an invalid log level being passed). When calling a logger, we should not need to concern ourselves with potential transport-level errors.
A destructor might be a special case in that regard because we cannot really tell when it's called. I see several ways to fix this:
Throwable
.I would think it best practice to not depend on any infrastructure during destructuring. From my perspective this is also a recently introduced issue or a regression
I'd vote in favour of removing the log call from the destruct; seems pretty redundant to be completely honest.
seems pretty redundant to be completely honest
It is very useful in the cases of long-running applications and other cases like the test suite where the number of simultaneously open connections is more than one. I used it to address the issues like https://github.com/doctrine/dbal/pull/4521.
I'm inclined to close this issue as "invalid" since the consumer of the middleware API violates its contract:
@dave-redfern Can we try to take this issue to Monolog? I feel like it should be possible to configure a logger that does not crash in such situations.
@dave-redfern Can we try to take this issue to Monolog? I feel like it should be possible to configure a logger that does not crash in such situations.
Sure, if you believe that is the best course of action. As I mentioned in an earlier comment, the issue is in the usage of the console terminate event in the Symfony monolog bridge, actively closing the log handlers. So maybe that is the best place rather than monolog directly?
Not sure, why MonologBundle would do that. All connections should be terminated by PHP itself anyway when the process ends.
What I was talking about is the PSR-3 contract that does not really declare an error state for loggers. So a logger that crashes if I write to it somewhat feels like a violation of PSR-3.
Sorry for pulling you into this debate, @Seldaek, maybe you've got some insights on where this issue could be addressed?
Re 3: the onTerminate
method is registered to the ConsoleEvent::TERMINATE
(see next method down: getSubscribedEvents), which is in turn raised in the base SF\Console\Application class: https://github.com/symfony/symfony/blob/134a5f190d6547c274255195a49882508fe5f731/src/Symfony/Component/Console/Application.php#L1021 at the end of every command execution.
@dave-redfern I am aware, but that only closes the ConsoleHandler, as far as I can tell it does not close all handlers, so where is your SyslogUdpHandler being closed?
I'm actually currently on holiday so don't have my computer to hand (responding from my iPad) so it's making it difficult for me to retrace the path and I don't have any of the debugging I previously did to hand.
Can you wait 2 weeks until I am back home so I can redo the back-tracing?
3. I don't understand where the close() happens, ConsoleHandler only closes itself AFAICT
It extends Monolog\Handler\AbstractProcessingHandler
, so it is the handler 🙈
It extends
Monolog\Handler\AbstractProcessingHandler
, so it is the handler 🙈
It is a handler, the ConsoleHandler. But the SyslogUdpHandler is another handler instance, which has to be closed individually.
Thanks for everyones patience. I've spent some time debugging and determined that the ->close()
is actually being called from the parent Monolog\Handler\Handler::__destruct()
during the final script shutdown. The console terminate was a mistaken path so please accept my apologies for any confusion.
Based on what I have observed: the socket used in the SyslogUdpHandler
is getting closed before any other handlers. That means that when DBAL\Logging\Connection::__destruct()
is finally fired, the socket is already gone. I confirmed this by using dump($this->logger)
on the DBAL connection logger and the socket property of the UdpSocket
is null:
^ Symfony\Bridge\Monolog\Logger^ {#121
#name: "doctrine"
#handlers: & array:1 [
0 => Monolog\Handler\SyslogUdpHandler^ {#414
#socket: Monolog\Handler\SyslogUdp\UdpSocket^ {#420
#ip: "host"
#port: 514
#socket: null
}
}
]
By adding a dump(class . ' destruct')
to various __destruct methods I observe the following (though order is arbitrary, I always see this output during my debugging):
^ "Monolog\Handler\SyslogUdpHandler destruct"
^ "Symfony\Bridge\Monolog\Handler\ConsoleHandler destruct"
^ "Monolog\Handler\NullHandler destruct"
^ "Doctrine\DBAL\Logging\Connection destruct"
I can avoid the issue by adding a console event listener that closes any open DBAL connections on terminate/error events but that seems less than ideal.
@dave-redfern, thanks for the details. But I still don't understand why is it necessary to close the logger in the first place. What will happen if it doesn't get closed?
In general, the close()
operations (be it a logger or a network connection, or any other resource) seem pointless and even harmful in PHP where on the one hand all resources are closed automatically at the end of request, and on the other hand, it is possible to implement a destructor.
Unless a resource can reopen automatically (see the DBAL wrapper connection for example), calling close()
on an object brings it to an unusable state making all its dependencies unusable as well.
@dave-redfern, thanks for the details. But I still don't understand why is it necessary to close the logger in the first place. What will happen if it doesn't get closed?
That would be a question for @Seldaek
If it does not get closed it will eventually be closed on destruct. I am not sure why Symfony is closing all handlers on kernel.terminate. I can see one advantage in that it is more deterministic, but here it's deterministically broken so not great. Another point is perhaps that when running in long running processes serving many web requests (app servers in php), closing things explicitly is better than hoping destruct will happen correctly?
Anyway I did fix the UdpSocket issue in https://github.com/Seldaek/monolog/releases/tag/2.6.0 so that the socket will reopen on demand, which should fix the issue here.
Speaking of determinism, it looks like something like the dependency injection container should be in charge of closing resources since it's aware of all the dependencies. Not just a random component closing a random resource.
Thanks, everybody for the details. I believe we can close the issue for now.
This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.
Bug Report
Summary
The
DBAL\Logging\Connection
middleware uses__destruct()
to call into the logger to logDisconnecting
but when using syslog (or potentially any logger with a remote resource) with monolog, the syslog connection can be terminated before the DBAL middleware drops out of scope. This causes a fatal error from the monolog UdpSocket, halting execution:Example stack trace:
Current behaviour
Exception terminating process, which if in docker entry point halts the image from running.
How to reproduce
composer create-project symfony/skeleton test-app
)composer req orm log
)namespace App\Entity;
use Doctrine\ORM\Mapping as ORM;
/**
@ORM\Entity() */ class User { /**
public function __construct(string $name) { $this->name = $name; } }
bin/console doctrine:schema:validate
Doctrine\DBAL\Logging\Connection
Expected behaviour
Logging middleware should not cause exceptions and can be prevented by removing the
__destruct()
logger call or wrapping in a try {} catch {}.