Upgrading from 2.16.3 to 2.17.0 breaks serialization when using symfony/var-exporter

[alcohol]

BC Break Report

Could not find anything in release notes so far that predicted this would break. Was also not yet able to determine which, if any, of the changes listed cause this behaviour. Will update this issue as I get further along.

Stacktrace is as follows (omitted a few lines at the bottom for brevity):

TypeError:
Doctrine\DBAL\Connection::executeQuery(): Argument #1 ($sql) must be of type string, null given, called in /srv/vendor/doctrine/orm/lib/Doctrine/ORM/Query/Exec/SingleSelectExecutor.php on line 33

  at vendor/doctrine/dbal/src/Connection.php:1071
  at Doctrine\DBAL\Connection->executeQuery(null, array(), array(), null)
     (vendor/doctrine/orm/lib/Doctrine/ORM/Query/Exec/SingleSelectExecutor.php:33)
  at Doctrine\ORM\Query\Exec\SingleSelectExecutor->execute(object(Connection), array(), array())
     (vendor/doctrine/orm/lib/Doctrine/ORM/Query.php:327)
  at Doctrine\ORM\Query->_doExecute()
     (vendor/doctrine/orm/lib/Doctrine/ORM/AbstractQuery.php:1212)
  at Doctrine\ORM\AbstractQuery->executeIgnoreQueryCache(null, 3)
     (vendor/doctrine/orm/lib/Doctrine/ORM/AbstractQuery.php:1166)
  at Doctrine\ORM\AbstractQuery->execute(null, 3)
     (vendor/doctrine/orm/lib/Doctrine/ORM/AbstractQuery.php:937)
  at Doctrine\ORM\AbstractQuery->getScalarResult()
     (vendor/doctrine/orm/lib/Doctrine/ORM/Tools/Pagination/Paginator.php:153)
  at Doctrine\ORM\Tools\Pagination\Paginator->getIterator()
  at iterator_to_array(object(Paginator))
     (src/<redacted>/Doctrine/Repository/CategoryRepository.php:46)
  at <redacted>\Doctrine\Repository\CategoryRepository->getRootCategories(25, 0)
     (src/<redacted>/CategoryBundle/Menu/MenuBuilder.php:119)
  at <redacted>\CategoryBundle\Menu\MenuBuilder->getCategoryTreeMenu(object(MenuItem), true)
     (src/<redacted>/CategoryBundle/Menu/MenuBuilder.php:114)
  at <redacted>\CategoryBundle\Menu\MenuBuilder->createMobileCategoryMenu(object(RequestStack))
     (var/cache/nl/docker/ContainerKpuxm9P/getPsCategory_Menu_MobileCategoriesService.php:23)
  at ContainerKpuxm9P\getPsCategory_Menu_MobileCategoriesService::do(object(AppKernelDockerDebugContainer), true)
     (var/cache/nl/docker/ContainerKpuxm9P/AppKernelDockerDebugContainer.php:898)
  at ContainerKpuxm9P\AppKernelDockerDebugContainer->load('getPsCategory_Menu_MobileCategoriesService.php')
     (var/cache/nl/docker/ContainerKpuxm9P/getKnpMenu_MenuProvider_LazyService.php:22)
  at ContainerKpuxm9P\getKnpMenu_MenuProvider_LazyService::ContainerKpuxm9P\{closure}(array())
     (vendor/knplabs/knp-menu/src/Knp/Menu/Provider/LazyProvider.php:39)
  at Knp\Menu\Provider\LazyProvider->get('mobile_categories', array())
     (vendor/knplabs/knp-menu/src/Knp/Menu/Provider/ChainProvider.php:26)
  at Knp\Menu\Provider\ChainProvider->get('mobile_categories', array())
     (vendor/knplabs/knp-menu/src/Knp/Menu/Twig/Helper.php:43)
  at Knp\Menu\Twig\Helper->get('mobile_categories', array())
     (vendor/knplabs/knp-menu/src/Knp/Menu/Twig/Helper.php:142)
  at Knp\Menu\Twig\Helper->castMenu('mobile_categories')
     (vendor/knplabs/knp-menu/src/Knp/Menu/Twig/Helper.php:75)

Q	A
BC Break	yes
Version	2.17.0

Summary

See stacktrace above.

Previous behavior

No exception was thrown.

Current behavior

Exception is thrown.

How to reproduce

Hard to tell, might be related to our code, might not be? Still debugging.

---

Update(s)

It seems that turning on lazy ghosts resolves the issue. However, that does not seem to be the default configuration in our symfony application. Is this the right way to deprecate something?

Turning it back off does not break things. Looking more likely to be cache related, making this a non-issue. Will try a new deployment with some more rigorous cache purging.

Sigh. Works on development environment now, broken on production still. More debugging needed.

[kerbert101]

2a9390d seems to be causing this

[itarcontact]

Hi. I have the same error. Reverting to 2.16.3 solves the problem.

[alcohol]

For me it was resolved by purging our cache more explicitly.

[kerbert101]

I can fix the issue by replacing the code that returns the properties to be serialized.

In AbstractSqlExecutor in the __sleep method:

return array_values(array_diff(array_keys(get_object_vars($this)), ["_sqlStatements"]));

[itarcontact]

@alcohol Which version do you finally have?

[alcohol]

I take it back, development release works (but runs in development mode). Production broken again. Manually purging caches did not resolve it there. Diving back into what the cause is.

[alcohol]

Weird, locally and on development we use

framework:
  annotations:
    cache: php_array

On production we use

framework:
  annotations:
    cache: file

Switching to file locally, installing 2.16.3 and then upgrading to 2.17.0 breaks things. But removing the cache directories solves it. We perform the same step during a production deployment though. So I'm confused why that does not resolve it. Maybe fpm file cache related? Going to see if a stop, cache purge, start - solves it.

---

Update

Still broken on production. Working fine locally and on development. Investigating further..

[KhorneHoly]

Upgrade to 2.17.0 also broke our code, downgrading to 2.16.3 now.

[RobinDev]

Same here in prod : purging the cache offers me a few request working, then same error. Investigating too.

[PhilETaylor]

For me it was resolved by purging our cache more explicitly.

This is what initially fixed it for me when I mentioned it here #11027 (comment) 2 weeks ago.

By "more explicitly", I mean I had to physically flush the Redis cache manually by flushing the whole redis db - for some reason the cli commands just did not clear the cache "enough".

Ive been running the new code in production for 2 weeks now with no issues since that day 2 weeks ago #11048

Is Redis the clue here? 🤷‍♂️

[alcohol]

I would prefer not to clear our entire Redis cache.. but it is worth investigating perhaps.

[greg0ire]

Clear the query cache (not the result cache, just the query cache) should be sufficient. What happened is I made the serialization format compatible with 3.0.x, so now all mentions of _sqlStatements in the cache should be replaced with sqlStatements, but 2.17.0 should still be able to deserialize an old version of the cache, thanks to

orm/lib/Doctrine/ORM/Query/Exec/AbstractSqlExecutor.php

Lines 92 to 94 in e8afa9f

	if ($this->_sqlStatements !== null && $this->sqlStatements === null) {
	$this->sqlStatements = $this->_sqlStatements;
	}

My assumption when writing this piece of code is that you cannot have both properties null at the same time after deserialization.

[alcohol]

That is a part of our release workflow though; so that is not sufficient unfortunately 😞

[itarcontact]

@PhilETaylor probably yes. We also use redis and cannot do flush it in the prod environment. This is why we have reverted to 2.16.3.

[alcohol]

Is null the correct value to check though? What about using isset() instead?

[greg0ire]

I think so yes

[greg0ire]

If anyone can reproduce this with a test, it would help a lot. The test could be contributed here: https://github.com/doctrine/orm/blob/2.17.x/tests/Doctrine/Tests/ORM/Functional/ParserResultSerializationTest.php

[alcohol]

I'm at a loss then kind of.

Our own code where the issue starts is:

    /** @return Category[] */
    public function getRootCategories(?int $limit = null, ?int $offset = null): array
    {
        $builder = $this->createQueryBuilder('c');
        $builder
            ->select('c', 't')
            ->leftJoin('c.translations', 't')
            ->where($builder->expr()->isNull('c.parent'))
            ->orderBy('c.weight', Criteria::ASC)
            ->setMaxResults($limit)
            ->setFirstResult($offset)
        ;

        return iterator_to_array(new Paginator($builder->getQuery()));
    }

This is a custom repository class that extends Gedmo\Tree\Entity\Repository\NestedTreeRepository and implements Doctrine\Bundle\DoctrineBundle\Repository\ServiceEntityRepositoryInterface

The entity it manages implements Knp\DoctrineBehaviors\Contract\Entity\TranslatableInterface and uses Knp\DoctrineBehaviors\Model\Translatable\TranslatableTrait, hence the translations being left joined in the builder.

From there on onwards though it is all Doctrine vendor code.

It even explicitly calls executeIgnoreQueryCache so I don't think the query cache is related to this.

[greg0ire]

I would be very surprised if this is unrelated to my change wrt the query cache.

Here is what a cache entry should look like:

orm/tests/Doctrine/Tests/ORM/Functional/ParserResults/single_select_2_17_0.txt

Line 1 in e8afa9f

O:31:"Doctrine\ORM\Query\ParserResult":3:{s:44:"Doctrine\ORM\Query\ParserResultsqlExecutor";O:44:"Doctrine\ORM\Query\Exec\SingleSelectExecutor":2:{s:16:"*sqlStatements";s:371:"SELECT c0_.id AS id_0, c0_.name AS name_1, c1_.salary AS salary_2, c1_.department AS department_3, c1_.startDate AS startDate_4, c2_.title AS title_5, c0_.discr AS discr_6, c0_.spouse_id AS spouse_id_7, c2_.car_id AS car_id_8 FROM company_employees c1_ INNER JOIN company_persons c0_ ON c1_.id = c0_.id LEFT JOIN company_managers c2_ ON c1_.id = c2_.id WHERE c0_.name = ?";s:20:"*queryCacheProfile";N;}s:49:"Doctrine\ORM\Query\ParserResultresultSetMapping";O:35:"Doctrine\ORM\Query\ResultSetMapping":19:{s:7:"isMixed";b:0;s:8:"isSelect";b:1;s:8:"aliasMap";a:1:{s:1:"u";s:45:"Doctrine\Tests\Models\Company\CompanyEmployee";}s:11:"relationMap";a:0:{}s:14:"parentAliasMap";a:0:{}s:13:"fieldMappings";a:6:{s:4:"id_0";s:2:"id";s:6:"name_1";s:4:"name";s:8:"salary_2";s:6:"salary";s:12:"department_3";s:10:"department";s:11:"startDate_4";s:9:"startDate";s:7:"title_5";s:5:"title";}s:14:"scalarMappings";a:0:{}s:12:"enumMappings";a:0:{}s:12:"typeMappings";a:3:{s:7:"discr_6";s:6:"string";s:11:"spouse_id_7";s:7:"integer";s:8:"car_id_8";s:7:"integer";}s:14:"entityMappings";a:1:{s:1:"u";N;}s:12:"metaMappings";a:3:{s:7:"discr_6";s:5:"discr";s:11:"spouse_id_7";s:9:"spouse_id";s:8:"car_id_8";s:6:"car_id";}s:14:"columnOwnerMap";a:9:{s:4:"id_0";s:1:"u";s:6:"name_1";s:1:"u";s:8:"salary_2";s:1:"u";s:12:"department_3";s:1:"u";s:11:"startDate_4";s:1:"u";s:7:"title_5";s:1:"u";s:7:"discr_6";s:1:"u";s:11:"spouse_id_7";s:1:"u";s:8:"car_id_8";s:1:"u";}s:20:"discriminatorColumns";a:1:{s:1:"u";s:7:"discr_6";}s:10:"indexByMap";a:0:{}s:16:"declaringClasses";a:6:{s:4:"id_0";s:45:"Doctrine\Tests\Models\Company\CompanyEmployee";s:6:"name_1";s:45:"Doctrine\Tests\Models\Company\CompanyEmployee";s:8:"salary_2";s:45:"Doctrine\Tests\Models\Company\CompanyEmployee";s:12:"department_3";s:45:"Doctrine\Tests\Models\Company\CompanyEmployee";s:11:"startDate_4";s:45:"Doctrine\Tests\Models\Company\CompanyEmployee";s:7:"title_5";s:44:"Doctrine\Tests\Models\Company\CompanyManager";}s:18:"isIdentifierColumn";a:0:{}s:17:"newObjectMappings";a:0:{}s:24:"metadataParameterMapping";a:0:{}s:23:"discriminatorParameters";a:0:{}}s:50:"Doctrine\ORM\Query\ParserResultparameterMappings";a:1:{s:4:"name";a:1:{i:0;i:0;}}}

Can somebody produce a cache entry that produces a broken SingleSelectExecutor object?

[kerbert101]

It seems like the PhpFilesAdapter used in (our) production environment cannot serialize the properties returned by __sleep in AbstractSqlExecutor, which will result in null values in the cache. Changing the code in AbstractSqlExecutor to return the properties without the \0*\0 prefix seems to fix the issue. I'm not sure if this will cause other issues, but this seems to fix it:

return array_values(array_diff(array_keys(get_object_vars($this)), ["_sqlStatements"]));

[kerbert101]

With the code above:

➜  system git:(master) grep -ir "SqlStatemen" *                                                               
6R70MIgpdM/Z/P/18gNFO5JUiaR9dDGtcRg:            'sqlStatements' => [

The faulty code does not return anything, meaning the sqlStatements key is not being filled at all.

[greg0ire]

@kerbert101 what's weird is that the piece of code you're modifying is the one that governs serialization. Its goal is to ensure _sqlStatements is not serialized (since we have sqlStatements). Why are you switching to get_object_vars(), BTW?

[kerbert101]

@greg0ire Yes, I'm aware of the fact that it governs what to serialize. I'm switching to get_object_vars to get rid of the \0x\0 prefixes, which I thought was causing the issue.

As you can see in the grep result, my modification will still ensure sqlStatements is serialized, not _sqlStatements.

Anyways, i'm not saying this is the fix, but this is what I see

[greg0ire]

Ok… I'm trying to simplify, but both seem to work the same:

• https://3v4l.org/MTP9k
• https://3v4l.org/4N37P

So why did I use (array) $this? Well, get_object_vars() does not seem to work with inheritance: https://3v4l.org/ce10i

[alcohol]

But do we have parent classes here? The properties are protected, not private, and they are implemented by children of the abstract class.

[alcohol]

Weird that there is a notice, I don't see one when running the test that contains this:

orm/tests/Doctrine/Tests/ORM/Functional/ParserResultSerializationTest.php

Line 36 in e8afa9f

$serialized = serialize($parserResult);

It's triggered by the exporter using trigger_error(sprintf('serialize(): "%s" returned as member variable from __sleep() but does not exist', $n), \E_USER_NOTICE);.

[nicolas-grekas]

Let me be more explicit: __sleep must return property names, not property identifiers. The difference is the \0-based prefix. __sleep cannot return any of them.

[greg0ire]

OK. So this is a Symfony bug, right?

[nicolas-grekas]

Nope, it's a Doctrine bug, __sleep must return property names without the \0-based prefix.

[alcohol]

@nicolas-grekas I do think you are correct in that __sleep should return just their plain names, not magic names. But I believe @greg0ire used this approach for reasons and it somehow works with just plain php serialize/unserialize.

[greg0ire]

How is it a Doctrine bug if everything works (there is not even a notice if I understood correctly) when using serialize, but it breaks when using VarExporter? Can somebody reproduce the bug in a test using Doctrine APIs and only them?

[nicolas-grekas]

It works because it's broken : __sleep fails and then php likely falls back to standard behavior, ignoring __sleep, thus generating a serialized payload that works, but doesn't achieve the wanted compatibility I'd say. It's my guess at least :)

[nicolas-grekas]

And the difference of behavior might be related to VarExporter not falling back to the exact same behavior when __sleep returns a broken payload. That'd explain everything. But the root issue is in Doctrine.

[greg0ire]

@nicolas-grekas I think it works just fine: https://3v4l.org/3ckU7 If PHP was falling back to standard behavior then we would see 2 properties, and here there is just sqlStatements.

[nicolas-grekas]

Oh, OK! Then you're relying on undocumented behavior of __sleep! (and unimplemented in VarExporter)

[greg0ire]

Yeah that sounds more plausible 😅
My process wasn't to go through the docs, but I stumbled upon other occurrences of \0 in the code, then on this: https://www.phpinternalsbook.com/php5/classes_objects/serialization.html

It's not part of the official docs, but I thought it would be good enough.

The other occurrences, for reference:

orm/lib/Doctrine/ORM/Query/ParserResult.php

Lines 143 to 144 in e8afa9f

	$this->$property = $data[sprintf("\0%s\0%s", self::class, $legacyProperty)]
	?? $data[sprintf("\0%s\0%s", self::class, $property)]

I think to address this, a possibility might be to iterate of the result of (array) $this and strip the \0*\0 part, before doing the diff with ['_sqlStatements']. That prefix, is probably here for a reason though 🤔 … avoiding collisions?

[nicolas-grekas]

\0*\0 is needless, __sleep works with protected properties without the prefix. The prefix might be required for private properties of parent classes. If that doesn't apply to this use case, removing the prefix is the right workaround for Doctrine.

[greg0ire]

I think it would work just fine, unless somebody external to Doctrine have their own extending class, with their own _sqlStatements private property defined in it… pretty far-fetched.

[kerbert101]

@greg0ire #11065

[greg0ire]

@kerbert101 thanks for working on this!

[nicolas-grekas]

Fix for Symfony: symfony/symfony#52618

Thank you all for the help on this one!

[symfonyaml]

Upgrading from 2.16.3 to 2.17.0 on my project break only in prod environment (not dev or test) with this error :

Uncaught PHP Exception TypeError: "Doctrine\DBAL\Connection::executeQuery():
Argument #1 ($sql) must be of type string, null given,
called in vendor/doctrine/orm/lib/Doctrine/ORM/Query/Exec/SingleSelectExecutor.php on line 33

which means $this->_sqlStatements is NULL ... if it helps.

[greg0ire]

Thanks, but we have 2 fixes on the way already, and pinpointed the issue a few messages ago. You just need to wait for either a new version of doctrine/orm or symfony/var-exporter.

[szczyglis-dev]

Hi, I've got the same issue after upgrade to 2.17.0. It only happens in prod env. I had to roll back to 2.16.3.

User Notice: serialize(): at /var/www/html/<site>/vendor/symfony/var-exporter/Internal/Exporter.php:164
Doctrine\DBAL\Connection::handleExceptionDuringQuery(): Argument #2 ($sql) must be of type string, null given, /var/www/html/<site>/vendor/doctrine/dbal/lib/Doctrine/DBAL/Connection.php on line 1538

Stacktrace:

Doctrine\DBAL\Connection::handleExceptionDuringQuery(): Argument #2 ($sql) must be of type string, null given, called in /var/www/html/<site>/vendor/doctrine/dbal/lib/Doctrine/DBAL/Connection.php on line 1538

/var/www/html/<site>/vendor/doctrine/dbal/lib/Doctrine/DBAL/Connection.php:2219
/var/www/html/<site>/vendor/doctrine/dbal/lib/Doctrine/DBAL/Connection.php:1538
/var/www/html/<site>/vendor/doctrine/orm/lib/Doctrine/ORM/Query/Exec/SingleTableDeleteUpdateExecutor.php:45
/var/www/html/<site>/vendor/doctrine/orm/lib/Doctrine/ORM/Query.php:327
/var/www/html/<site>/vendor/doctrine/orm/lib/Doctrine/ORM/AbstractQuery.php:1212
/var/www/html/<site>/vendor/doctrine/orm/lib/Doctrine/ORM/AbstractQuery.php:1166
/var/www/html/<site>/src/Repository/Status/UpdateTrait.php:62

(rest of trace)

[greg0ire]

@szczyglis-dev I said: YOU JUST NEED TO WAIT

So just wait. No need for more reports.

[greg0ire]

https://github.com/doctrine/orm/releases/tag/2.17.1 released

[alcohol]

Awesome, many thanks to everyone who got involved so quickly to resolve this 🥳 !