Unable to login in production when getUserIdentifier uses an entity and monolog fingers_crossed handler set to "error"

[gremo]

Symfony version(s) affected

7.0

Description

I spent literally days to find out this bug. It was really a nightmare. Title may sound strange and if fact this bug is really odd.

When

1. You are in production
2. You implement getUserIdentifier using a related entity, in my example User has a many-to-one non-nullable relation to AppProfile:

public function getUserIdentifier(): string
{
  return sprintf('%s@%s', $this->username, $this->profile->getCode());
}

3. In your monolog.yaml configuration, you are using the "fingers_crossed" handler with an action_level set to "error"

when@prod:
    monolog:
        handlers:
            filter_for_errors:
                type: fingers_crossed
                # if *one* log is error or higher, pass *all* to file_log
                action_level: error
                handler: file_log

            # now passed *all* logs, but only if one log is error or higher
            file_log:
                type: stream
                path: "%kernel.logs_dir%/%kernel.environment%.log"

What happens

1. You will not be able to login at all
2. There are no errors in var/log/prod.log, you can't figure out what's happening

What I've tried

public function getUserIdentifier(): string
{
  // Doesn't work anyways
  return sprintf('%s@%s', $this->username, (string) $this->profile->getCode());

  // No issues (this is not a problem related to null values passed to sprintf)
  return sprintf('%s@%s', $this->username, null);

  // No issues
  return $this->username;
}

What's even stranger

In your monolog.yaml configuration set action_level to "debug" instead of "error" and login will always work.

How to reproduce

https://github.com/gremo/symfony-login-bug

Possible Solution

No response

Additional Context

Inside getUserIdentifier, when you click "login", the $this->profile member is actually a Doctrine Proxy:

public function getUserIdentifier(): string
{
  dd($this->profile);
  return sprintf('%s@%s', $this->username, $this->profile->getCode());
}

My original issue on monolog-bundle repository: symfony/monolog-bundle#476

[HypeMC]

This isn't a bug in Symfony, it's more about how you're using it. The main problem is that once a Doctrine proxy is serialized and then deserialized, lazy loading no longer works. Therefore, if code isn't loaded beforehand, your login fails as the identifier has changed (foo@ instead of foo@localhost).

Now, the reason it works when you set action_level: debug is because the data serialized is different in these two cases:

• action_level: error: O:74:"Symfony\Component\Security\Core\Authentication\Token\UsernamePasswordToken":3:{i:0;N;i:1;s:4:"main";i:2;a:5:{i:0;O:15:"App\Entity\User":6:{s:19:" App\Entity\User id";i:1;s:25:" App\Entity\User username";s:3:"foo";s:25:" App\Entity\User password";s:32:"37b51d194a7513e45b56f6524f2d51f2";s:22:" App\Entity\User roles";a:0:{}s:35:" App\Entity\User passwordHasherName";s:3:"md5";s:24:" App\Entity\User profile";O:36:"Proxies_CG_\App\Entity\AppProfile":1:{s:25:" App\Entity\AppProfile id";i:1;}}i:1;b:1;i:2;N;i:3;a:0:{}i:4;a:1:{i:0;s:9:"ROLE_USER";}}}
• action_level: debug: O:74:"Symfony\Component\Security\Core\Authentication\Token\UsernamePasswordToken":3:{i:0;N;i:1;s:4:"main";i:2;a:5:{i:0;O:15:"App\Entity\User":6:{s:19:" App\Entity\User id";i:1;s:25:" App\Entity\User username";s:3:"foo";s:25:" App\Entity\User password";s:32:"37b51d194a7513e45b56f6524f2d51f2";s:22:" App\Entity\User roles";a:0:{}s:35:" App\Entity\User passwordHasherName";s:3:"md5";s:24:" App\Entity\User profile";O:36:"Proxies_CG_\App\Entity\AppProfile":2:{s:25:" App\Entity\AppProfile id";i:1;s:27:" App\Entity\AppProfile code";s:9:"localhost";}}i:1;b:1;i:2;N;i:3;a:0:{}i:4;a:1:{i:0;s:9:"ROLE_USER";}}}

So why is it different? Basically, Monolog triggers the AppProfile to get loaded while writing debug information. Once the debug information is not written, the entity is never loaded, so code remains null.

I'm not sure how good an idea it is to use relations in identifiers, but one workaround would be to use eager loading:

#[ORM\Entity()]
class User implements
    UserInterface,
    PasswordAuthenticatedUserInterface,
    PasswordHasherAwareInterface
{
-   #[ORM\ManyToOne]
+   #[ORM\ManyToOne(fetch: 'EAGER')]
    #[ORM\JoinColumn(nullable: false, onDelete: 'CASCADE')]
    private ?AppProfile $profile = null;

    // ...
}

[gremo]

@HypeMC thank you for your great and detailed information. This behaviour gave me a lot of headaches!

I'm going to close since isn't a real issue (hope that other devs can quickly find the source of the problem, thanks to this reporting).