DBAL logging connection __destruct can be run after the logger has closed

[dave-redfern]

Bug Report

Q	A
Version	3.3.4

Summary

The DBAL\Logging\Connection middleware uses __destruct() to call into the logger to log Disconnecting 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:

PHP Fatal error:  Uncaught RuntimeException: The UdpSocket to syslog:514 has been closed and can not be written to anymore in /app/vendor/monolog/monolog/src/Monolog/Handler/SyslogUdp/UdpSocket.php:63
Stack trace:
#0 /app/vendor/monolog/monolog/src/Monolog/Handler/SyslogUdp/UdpSocket.php(49): Monolog\Handler\SyslogUdp\UdpSocket->send()
#1 /app/vendor/monolog/monolog/src/Monolog/Handler/SyslogUdpHandler.php(77): Monolog\Handler\SyslogUdp\UdpSocket->write()
#2 /app/vendor/monolog/monolog/src/Monolog/Handler/AbstractProcessingHandler.php(48): Monolog\Handler\SyslogUdpHandler->write()
#3 /app/vendor/monolog/monolog/src/Monolog/Logger.php(328): Monolog\Handler\AbstractProcessingHandler->handle()
#4 /app/vendor/monolog/monolog/src/Monolog/Logger.php(527): Monolog\Logger->addRecord()
#5 /app/vendor/doctrine/dbal/src/Logging/Connection.php(30): Monolog\Logger->info()
#6 [internal function]: Doctrine\DBAL\Logging\Connection->__destruct()
#7 {main}

Current behaviour

Exception terminating process, which if in docker entry point halts the image from running.

How to reproduce

• start a new SF skeleton project (composer create-project symfony/skeleton test-app)
• add monolog and doctrine (composer req orm log)
• setup db connection (sqlite, pg whatever)
• setup monolog with a syslog connection

when@dev:
    monolog:
        handlers:
            main:
                type: syslogudp
                host: "syslog.server.host"
                port: "514"
                facility: local1
                ident: "test-app"
                level: debug
                channels: [ "!event" ]

• add an entity with basic annotations

<?php declare(strict_types=1);

namespace App\Entity;

use Doctrine\ORM\Mapping as ORM;

/**
 * @ORM\Entity()
 */
class User
{
    /**
     * @ORM\Id()
     * @ORM\GeneratedValue()
     * @ORM\Column(type="integer")
     */
    public ?int $id = null;
    /**
     * @ORM\Column(type="string", length=255)
     */
    public string $name;

    public function __construct(string $name)
    {
        $this->name = $name;
    }
}

• run bin/console doctrine:schema:validate
• error with UdpSocket closed originating from 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 {}.

[morozov]

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

[dave-redfern]

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.

[morozov]

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.

[dave-redfern]

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.

[morozov]

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

[derrabus]

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:

• Add a decorator around the logger that stops logging as soon as the logger is closed. That decorator could even be a part of Monolog itself.
• Patch Monolog to discard calls to closed loggers (or make this behavior configurable).
• In DBAL's logger middleware, wrap the logger call inside the destructor in a try/catch and discard any Throwable.
• Don't log inside the destructor at all.

[chrisnoden]

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

[dave-redfern]

I'd vote in favour of removing the log call from the destruct; seems pretty redundant to be completely honest.

[morozov]

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 #4521.

[morozov]

I'm inclined to close this issue as "invalid" since the consumer of the middleware API violates its contract:

1. The middleware accepts a logger via its constructor which implies that the logger should be ready before the middleware is constructed and up until it's destructed.
2. The API consumer implements manual resource management on the logger without taking into account its dependents. If it's necessary to close the log, the connection should be closed prior to that.
3. The recommendation not to rely on infrastructure in destructors makes sense in general for complex/legacy systems where circular dependencies are by design and are impossible to address. In this case, the order of object destruction would be indeed not guaranteed. This is a way to prevent symptoms without fixing the root cause. But it's not the case here. The API consumer violates the API contract and should be fixed instead.

[derrabus]

@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]

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

[derrabus]

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?

[Seldaek]

1. IMO a logger crashing if it cannot log is a good thing, as it should alert you that your logging isn't working. For those who disagree we offer the WhatFailureGroupHandler wrapper that suppresses errors.
2. Logging in __destruct may be risky, but in theory I also don't really see why you shouldn't be able to.
3. I don't understand where the close() happens, ConsoleHandler only closes itself AFAICT https://github.com/symfony/monolog-bridge/blob/6ce6f39536a718ec2ece37eae81c6899030fc571/Handler/ConsoleHandler.php#L130 - Maybe you're using another version of Symfony with different code in there tho?
4. The only thing I would consider fixing in Monolog is making sure that the SyslogUdpHandler stores the host/port instead of an open socket and then lazy connect it when writing, so that if it was closed it can be reopened instead of throwing. But this would only fix the symptom here, and other handlers may still fail as we cannot guarantee that all handlers can be used after close(). See https://github.com/Seldaek/monolog/blob/4192345e260f1d51b365536199744b987e160edc/src/Monolog/Handler/HandlerInterface.php#L68-L84

[dave-redfern]

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.

[Seldaek]

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

[dave-redfern]

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?

[morozov]

3. I don't understand where the close() happens, ConsoleHandler only closes itself AFAICT

It extends Monolog\Handler\AbstractProcessingHandler, so it is the handler 🙈

[Seldaek]

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.

[dave-redfern]

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.

[morozov]

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

[morozov]

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]

@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

[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.

[morozov]

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.

[github-actions]

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.