dbal: SQLLogger does not log actual params used in query

Bug Report

Q A
BC Break no
Version 2.12.1

Summary

There are scenarios when params logged by SQLLogger are not the same as params actually used in query. It’s because query, params and types are logged before preparing statement, in which params are bound (and while binding they can be typecasted which ends with different value than the one which was logged).

Initially reported in Symfony, after discussion in DoctrineBundle, then here after @ostrolucky’s request.

Current behaviour

When using query builder with something like:

$qb->andWhere("foo.value IN (:foo_values)");
$qb->setParameter("foo_values", ['bar'], Connection::PARAM_INT_ARRAY);

Doctrine data collector in Symfony profiler shows “runnable query” with foo.values IN ('bar') but actually database query contains foo.values IN (0) because of Connection::PARAM_INT_ARRAY param type. It is very misleading, because looking at the profiler you may think the query is correct (even though the result is not). Profiler displays data from collector, which works on top of SQLLogger, so DBAL is the source of query, params and types available later in the profiler.

More context can be found in doctrine/DoctrineBundle#1312

How to reproduce

Here’s reproducer created by @Nyholmhttps://github.com/Nyholm/sf-issue-40566

Expected behaviour

In the end user should know what params were actually used in query because it would allow to find bugs faster. Personally I’ve lost lot of time because I’ve seen in profiler wrong “runnable query”, which was returning different set of values than actual query in the app. I had to enable and watch general log in MySQL to see what’s actually executed and then was able to find source of the problem.

About this issue

  • Original URL
  • State: closed
  • Created 3 years ago
  • Comments: 21 (20 by maintainers)

Commits related to this issue

Most upvoted comments

1 warning : will that be about a loose comparison?

Yes:

mysql> show warnings;
+---------+------+-----------------------------------------+
| Level   | Code | Message                                 |
+---------+------+-----------------------------------------+
| Warning | 1292 | Truncated incorrect DOUBLE value: 'foo' |
+---------+------+-----------------------------------------+
1 row in set (0.00 sec)

Folks, this issue isn’t about mysql returning non-empty results, but about difficulty of debugging such problem in DBAL. I have created test case with result assertion only to demonstrate this WTF. Now imagine this happening accidentally - DBAL logger shows values you passed but they aren’t the values passed to mysql server. This is very tricky for user and I have posted some proposal to improve it in https://github.com/doctrine/dbal/issues/4602#issuecomment-825931120