PHP / Doctrine/DBAL: adding a logger to an connection

G'day:

There's plenty of stuff online about how to do this the old deprecated way, but I couldn't find any example of how to do it the "current" way. So. Here's an example.

NB: the old way is some variant of this sort of thing:

$logger = new \Doctrine\DBAL\Logging\DebugStack();
$config = new \Doctrine\DBAL\Configuration();
$config->setSQLLogger($logger);

$connection = DriverManager::getConnection(
    $connectionParams,
    $config
);

However both DebugStack and setSQLLogger are deprecated. The DebugStack thing is just a logger instance and I didn't want to use that anyhow, but being able to set the logger I did want to use would be nice.

I dug into setSQLLogger, and it says this:

@deprecated Use {@see setMiddlewares()} and {@see \Doctrine\DBAL\Logging\Middleware} instead.

OK we'll do that then.

I'll spare you the code, but initially I was trying to set the middlewares (I'm not sure(*) that's the plural of "middleware", guys) on an existing connection object, and that was not working at all. Nothing was being logged. Then I discovered someone else with the same woes as me @ https://github.com/doctrine/dbal/issues/5366, and apparently one cannot actually do this, as the middlewares are only paid-attention-to when the connection is first created, so I needed to pass the config in during connection-creation. This is not well-documented either, but looking at the source code answered that.

Here's what I ended up with in my test:

namespace adamcameron\php8\tests\Functional\Database;

use adamcameron\php8\tests\Integration\Fixtures\Database as DB;
use Doctrine\DBAL\Configuration;
use Doctrine\DBAL\Logging\Middleware;
use Monolog\Handler\TestHandler;
use Monolog\Logger;
use PHPUnit\Framework\TestCase;

/** @testdox Tests Database objects */
class DbLoggingTest extends TestCase
{
    /** @testdox It can log SQL traffic */
    public function testLogging()
    {
        $testLogger = new Logger("test");
        $testHandler = new TestHandler();
        $testLogger->setHandlers([$testHandler]);
        $middleware = new Middleware($testLogger);

        $config = new Configuration();
        $config->setMiddlewares([$middleware]);

        $connection = DB::getDbalConnection($config);

        $result = $connection->executeQuery("SELECT * FROM numbers WHERE id = ?", [5]);

        $this->assertEquals([5, 'five', 'rima'], $result->fetchNumeric());

        $withSql = array_filter($testHandler->getRecords(), function ($record) {
            return in_array('SELECT * FROM numbers WHERE id = ?', $record->context);
        });
        $this->assertCount(1, $withSql);
    }
}

Given Middleware only supports Loggers, I'm not sure this is a great architectural win for DBAL: moving from a clear and on-point description of the functionality to a nebulous, vague, and actually inaccurate term like "Middleware". Oh well.

For the sake of completeness (and an explanation of why I needed to dick around filtering the log to get the one I was looking for, this is what is logged for that call:

array(2) {
  [0] =>
  class Monolog\LogRecord#363 (7) {
    public readonly DateTimeImmutable $datetime =>
    class Monolog\DateTimeImmutable#357 (4) {
      private $useMicroseconds =>
      bool(true)
      public $date =>
      string(26) "2023-02-02 23:27:14.519171"
      public $timezone_type =>
      int(3)
      public $timezone =>
      string(13) "Europe/London"
    }
    public readonly string $channel =>
    string(4) "test"
    public readonly Monolog\Level $level =>
    enum Monolog\Level::Info : int(200);
    public readonly string $message =>
    string(35) "Connecting with parameters {params}"
    public readonly array $context =>
    array(1) {
      'params' =>
      array(6) {
        ...
      }
    }
    public array $extra =>
    array(0) {
    }
    public mixed $formatted =>
    string(204) "
        [2023-02-02T23:27:14.519171+00:00]
        test.INFO:
        Connecting with parameters {params}
        {
            "params":{
                "dbname":"db1",
                "user":"user1",
                "password":"<redacted>",
                "host":"mariadb",
                "port":"3306",
                "driver":"pdo_mysql"
            }
        }
        []
    "
  }
  [1] =>
  class Monolog\LogRecord#349 (7) {
    public readonly DateTimeImmutable $datetime =>
    class Monolog\DateTimeImmutable#348 (4) {
      private $useMicroseconds =>
      bool(true)
      public $date =>
      string(26) "2023-02-02 23:27:14.780537"
      public $timezone_type =>
      int(3)
      public $timezone =>
      string(13) "Europe/London"
    }
    public readonly string $channel =>
    string(4) "test"
    public readonly Monolog\Level $level =>
    enum Monolog\Level::Debug : int(100);
    public readonly string $message =>
    string(65) "Executing statement: {sql} (parameters: {params}, types: {types})"
    public readonly array $context =>
    array(3) {
      'sql' =>
      string(34) "SELECT * FROM numbers WHERE id = ?"
      'params' =>
      array(1) {
        ...
      }
      'types' =>
      array(1) {
        ...
      }
    }
    public array $extra =>
    array(0) {
    }
    public mixed $formatted =>
    string(194) "
        [2023-02-02T23:27:14.780537+00:00]
        test.DEBUG:
        Executing statement:
            {sql}
            (parameters: {params}, types: {types})
            {
                "sql":"SELECT * FROM numbers WHERE id = ?",
                "params":{
                    "1":5
                },
                "types":{
                    "1":2
                }
            }
        []
    "
  }
}

(Well that pads the word count…)

I like how it's had the presence of mind to redact the password from the connection params.

Anyway, that's it. I just wanted that code written down somewhere were it can be found.

Righto.

--
Adam

---

(*) In fact I've very bloody sure it oughtn't be (and, yesyesyes, I know it's been adopted as such, but this is LCD thinking at work. "-ware" already makes it a mass noun, so… plural).