UUID classes fail to be deserialized: incomplete object

[GinoPane]

Describe the bug

Got this error when using the library in "prod" environment (symfony 5 via ramsey/uuid-doctrine):

[2020-03-27T13:02:02.992541+00:00] php.CRITICAL: Fatal Error: Ramsey\Uuid\Provider\Node\FallbackNodeProvider::getNode(): The script tried to execute a method or access a property of an incomplete object. Please ensure that the class definition "Ramsey\Uuid\Provider\Node\SystemNodeProvider" of the object you are trying to operate on was loaded _before_ unserialize() gets called or provide an autoloader to load the class definition {"exception":"[object] (Symfony\\Component\\ErrorHandler\\Error\\FatalError(code: 0): Error: Ramsey\\Uuid\\Provider\\Node\\FallbackNodeProvider::getNode(): The script tried to execute a method or access a property of an incomplete object. Please ensure that the class definition \"Ramsey\\Uuid\\Provider\\Node\\SystemNodeProvider\" of the object you are trying to operate on was loaded _before_ unserialize() gets called or provide an autoloader to load the class definition at /usr/src/app/vendor/ramsey/uuid/src/Provider/Node/FallbackNodeProvider.php:47)"} {"token":"44058e05-57473988"}
[2020-03-27T13:02:03.000284+00:00] app.ERROR: Error: Ramsey\Uuid\Provider\Node\FallbackNodeProvider::getNode(): The script tried to execute a method or access a property of an incomplete object. Please ensure that the class definition "Ramsey\Uuid\Provider\Node\SystemNodeProvider" of the object you are trying to operate on was loaded _before_ unserialize() gets called or provide an autoloader to load the class definition [] {"token":"44058e05-47820505"}

It looks like the system tries to unserialize UUID for any reason and it fails. It is hard to reproduce, but maybe you've seen anything similar?

[ramsey]

Hi, @GinoPane! Thanks for the bug report.

Which version of ramsey/uuid are you using? Is there any code you can share to show how you are using it?

[GinoPane]

It's ramsey/uuid-doctrine 1.6.0

To be honest, the code is extremely generic. The fatal error happens on this code:

$user = (new User())
            ->setCreatedAt(new \DateTime());
$this->entityManager->persist($user);
$this->entityManager->flush();

Right after persist is being called. And before it we have a generic call to the session to get some stored user data.

Ah, and User entity has UUID ID:

    /**
     * @var UuidInterface
     *
     * @ORM\Id
     * @ORM\Column(type="uuid_binary_ordered_time", unique=true)
     * @ORM\GeneratedValue(strategy="CUSTOM")
     * @ORM\CustomIdGenerator(class="Ramsey\Uuid\Doctrine\UuidOrderedTimeGenerator")
     */
    private $id;

The most weird thing is that if I throw a generic exception from /vendor/ramsey/collection/src/AbstractCollection.php::unserialize the issue disappears and everything works fine. So it's extremely weird.

[GinoPane]

More digging gave these errors:

[2020-03-27T18:54:20.161327+00:00] cache.WARNING: Failed to fetch key "%5BApp%5CEntity%5CUser%24CLASSMETADATA%5D%5B1%5D": User Error: a:2:{i:0;O:31:"Ramsey\Uuid\Rfc4122\UuidBuilder":2:{s:48:" {"key":"%5BApp%5CEntity%5CUser%24CLASSMETADATA%5D%5B1%5D","exception":"[object] (ErrorException(code: 0): User Error: a:2:{i:0;O:31:\"Ramsey\\Uuid\\Rfc4122\\UuidBuilder\":2:{s:48:\" at /usr/src/app/vendor/ramsey/collection/src/AbstractCollection.php:356)"} []
[2020-03-27T18:54:20.256208+00:00] cache.WARNING: Failed to fetch key "%5BApp%5CEntity%5CUser%24CLASSMETADATA%5D%5B1%5D": User Error: a:2:{i:0;O:31:"Ramsey\Uuid\Rfc4122\UuidBuilder":2:{s:48:" {"key":"%5BApp%5CEntity%5CUser%24CLASSMETADATA%5D%5B1%5D","exception":"[object] (ErrorException(code: 0): User Error: a:2:{i:0;O:31:\"Ramsey\\Uuid\\Rfc4122\\UuidBuilder\":2:{s:48:\" at /usr/src/app/vendor/ramsey/collection/src/AbstractCollection.php:356)"} []
[2020-03-27T18:54:20.307382+00:00] cache.WARNING: Failed to fetch key "%5BApp%5CEntity%5CCrowdReply%24CLASSMETADATA%5D%5B1%5D": User Error: a:2:{i:0;O:31:"Ramsey\Uuid\Rfc4122\UuidBuilder":2:{s:48:" {"key":"%5BApp%5CEntity%5CCrowdReply%24CLASSMETADATA%5D%5B1%5D","exception":"[object] (ErrorException(code: 0): User Error: a:2:{i:0;O:31:\"Ramsey\\Uuid\\Rfc4122\\UuidBuilder\":2:{s:48:\" at /usr/src/app/vendor/ramsey/collection/src/AbstractCollection.php:356)"} []
[2020-03-27T18:54:20.353727+00:00] cache.WARNING: Failed to fetch key "%5BApp%5CEntity%5CCrowdReply%24CLASSMETADATA%5D%5B1%5D": User Error: a:2:{i:0;O:31:"Ramsey\Uuid\Rfc4122\UuidBuilder":2:{s:48:" {"key":"%5BApp%5CEntity%5CCrowdReply%24CLASSMETADATA%5D%5B1%5D","exception":"[object] (ErrorException(code: 0): User Error: a:2:{i:0;O:31:\"Ramsey\\Uuid\\Rfc4122\\UuidBuilder\":2:{s:48:\" at /usr/src/app/vendor/ramsey/collection/src/AbstractCollection.php:356)"} []
[2020-03-27T18:54:20.395748+00:00] cache.WARNING: Failed to fetch key "%5BApp%5CEntity%5CForm%24CLASSMETADATA%5D%5B1%5D": User Error: a:2:{i:0;O:31:"Ramsey\Uuid\Rfc4122\UuidBuilder":2:{s:48:" {"key":"%5BApp%5CEntity%5CForm%24CLASSMETADATA%5D%5B1%5D","exception":"[object] (ErrorException(code: 0): User Error: a:2:{i:0;O:31:\"Ramsey\\Uuid\\Rfc4122\\UuidBuilder\":2:{s:48:\" at /usr/src/app/vendor/ramsey/collection/src/AbstractCollection.php:356)"} []
[2020-03-27T18:54:20.444614+00:00] cache.WARNING: Failed to fetch key "%5BApp%5CEntity%5CForm%24CLASSMETADATA%5D%5B1%5D": User Error: a:2:{i:0;O:31:"Ramsey\Uuid\Rfc4122\UuidBuilder":2:{s:48:" {"key":"%5BApp%5CEntity%5CForm%24CLASSMETADATA%5D%5B1%5D","exception":"[object] (ErrorException(code: 0): User Error: a:2:{i:0;O:31:\"Ramsey\\Uuid\\Rfc4122\\UuidBuilder\":2:{s:48:\" at /usr/src/app/vendor/ramsey/collection/src/AbstractCollection.php:356)"} []

And as a result I found out that disabling of doctrine metadata cache solves the issue:

But the root cause is still inclear 🤷‍♂

[ramsey]

Thank you for the details. I'll start from the premise that something is broken in the unserialization methods and see if that leads me anywhere.

[GinoPane]

@ramsey great, thanks!

It would be great to have any kind of built-in check that unserialize was successful if it makes sense.
Obviously, in my case the actual issue lies within Doctrine metadata cache probably, we don't know yet why it cannot be properly read.

[ramsey]

I think this might be related to #259

[ramsey]

Strike that. It's not related to #259. I've been able to trace the problem to this commit in ramsey/collection (ramsey/collection@b05f542) that's related to ramsey/collection#47.

I'm working on a solution that fixes this in ramsey/uuid.

[ramsey]

@GinoPane, please upgrade to ramsey/uuid 4.0.1 and let me know if this fixes the errors you're seeing.

Since you're using ramsey/uuid-doctrine in your project, I think this this what you will need to run to force an update to the latest version of ramsey/uuid:

composer update --with-dependencies ramsey/uuid-doctrine

After doing this, you can see what version of ramsey/uuid is installed by running:

composer show ramsey/uuid

It should show version 4.0.1. If it does, and you're still seeing the errors, then I'll need to dig deeper.

Thanks!

[coxa]

Wow! Seems it works. Any way my problem regarding it is solved.

[GinoPane]

@ramsey thanks! The issue seems to be solved.
It was a nice one with so many levels.

[ramsey]

I’m glad it’s working now. Thank you for the bug report!