Authentication does not work with HHVM - user data is not persisted

[maurocolella]

The problem description is available from: http://stackoverflow.com/questions/24933045/silex-framework-user-is-always-anonymous

System: Ubuntu 14.04 Architecture: amd64 HHVM Version: 3.2.0~trusty Silex Version: ~1.1

Not tested with 1.2.

[henrikbjorn]

What does you Security Configuration look like?

[henrikbjorn]

Also before assuming its a HHVM problem, have you tried the same code running on "Vanilla" PHP?

[maurocolella]

Yes. Tried it on php5-fpm, authentication works and is persisted.

$app->register(new Silex\Provider\UrlGeneratorServiceProvider());
$app->register(new Silex\Provider\SessionServiceProvider());

/*
 * Security layer.
 */
$app->register ( new Silex\Provider\SecurityServiceProvider (), array (

        'security.firewalls' => array (

                /*'login_path' => array (

                        'pattern' => '^/login$',

                        'anonymous' => true
                )
                ,*/

                'default' => array (

                        'pattern' => '^/.*$',

                        'anonymous' => true,

                        'form' => array (

                                'login_path' => '/login',

                                'check_path' => '/auth'
                        )
                        ,

                        'logout' => array (

                                'logout_path' => '/logout',

                                'invalidate_session' => false
                        )
                        ,

                'users' => $app->share(function($app) {
                    $user = new BnB\UAC\UserProvider($app['db']);
                    //var_dump( $user->supportsClass('Symfony\Component\Security\Core\User\User') );
                    //die();
                    return $user;

                }),

            )
        )
        ,

        'security.access_rules' => array(

            //array('^/login$', 'IS_AUTHENTICATED_ANONYMOUSLY'),

            array('^/user$', 'ROLE_USER'),

            array('^/.+$', 'IS_AUTHENTICATED_ANONYMOUSLY')

        )

    ));

$app['security.encoder.digest'] = $app->share(function ($app) {
    // use the sha1 algorithm
    // don't base64 encode the password
    // use only 1 iteration
    return new MessageDigestPasswordEncoder('sha1', false, 1);
});

I am using a sha1 encoded password (password verification is not the problem).

The UserProvider class is the exact same as: http://www.bubblecode.net/en/2012/08/28/mysql-authentication-in-silex-the-php-micro-framework/

[davedevelopment]

Have you tried adding the monolog service provider, the security provider spits out quite a lot of debug logging that might help.

[henrikbjorn]

The issue is probably that you have anonymous: true before any of the other security providers, that way it will always first try that, and all your users are therefor anonymous.

[maurocolella]

@davedevelopment , thank you for the advice: I have just setup the monolog service provider, and it produces useful output.

@henrikbjorn not relevant. These are static definitions and it works with "vanilla" php5-fpm.

I get these two different outputs from monolog:

With HHVM [2014-07-24 09:55:52] myapp.INFO: Matched route "auth" (parameters: "_controller": "null", "route": "auth") [] [] [2014-07-24 09:55:52] myapp.INFO: User "justin" has been authenticated successfully [] [] [2014-07-24 09:55:52] myapp.INFO: < 302 http://mydomain/ [] [] [2014-07-24 09:55:52] myapp.DEBUG: Write SecurityContext in the session [] [] [2014-07-24 09:55:52] myapp.INFO: Matched route "GET" (parameters: "_controller": "{"0":{"0":null}}", "route": "GET") [] [] [2014-07-24 09:55:52] myapp.INFO: Populated SecurityContext with an anonymous Token [] [] [2014-07-24 09:55:52] myapp.INFO: > GET / [] [] [2014-07-24 09:55:52] myapp.INFO: < 200 [] []

With PHP FPM [2014-07-24 09:58:34] myapp.INFO: Matched route "auth" (parameters: "_controller": "null", "route": "auth") [] [] [2014-07-24 09:58:34] myapp.INFO: User "justin" has been authenticated successfully [] [] [2014-07-24 09:58:34] myapp.INFO: < 302 http://mydomain/ [] [] [2014-07-24 09:58:34] myapp.DEBUG: Write SecurityContext in the session [] [] [2014-07-24 09:58:35] myapp.INFO: Matched route "GET" (parameters: "_controller": "{}", "route": "GET") [] [] [2014-07-24 09:58:35] myapp.DEBUG: Read SecurityContext from the session [] [] [2014-07-24 09:58:35] myapp.DEBUG: Reloading user from user provider. [] [] [2014-07-24 09:58:35] myapp.DEBUG: Username "justin" was reloaded from user provider. [] [] [2014-07-24 09:58:35] myapp.INFO: > GET / [] [] [2014-07-24 09:58:35] myapp.INFO: < 200 [] []

So, it seems the problem lies with reading the security context from the session. The call never happens when running this code from HHVM. I suspect that the default implementation of the login check raises an uncaught exception of some sort, possibly due to stricter type checking in HHVM.

[davedevelopment]

https://github.com/symfony/symfony/blob/master/src/Symfony/Component/Security/Http/Firewall/ContextListener.php would be a good place to start debugging that.

[maurocolella]

Let me know how I can help.

[maurocolella]

For the record, I tried a few things, including:

• Clearing all my cookies.
• Making sure any additional http headers are not sent before a session is started.
• Making sure my sessions are registered.
• Making sure that Nginx in this case forwards authentication headers.
• Upgrading the security component to the latest development version of Symfony (2.6).

To no avail.

[ghost]

do the controller value differences not have anything to do with it? HHVM

[2014-07-24 09:55:52] myapp.INFO: Matched route "GET" (parameters: "controller": "{"0":{"0":null}}", "_route": "GET") [] []

PHP

[2014-07-24 09:58:35] myapp.INFO: Matched route "GET" (parameters: "controller": "{}", "_route": "GET") [] []

[TandFMachine]

I got it to work.

I simply used the PdoSessionStorageHandler instead of the default, native handler. http://silex.sensiolabs.org/doc/cookbook/session_storage.html

I did this because, from my HHVM log, the issue appears to lie with session data serialization in some contexts.

Warning: json_encode(): recursion detected in /var/www/quickstayz/silex/vendor/symfony/http-kernel/Symfony/Component/HttpKernel/EventListener/RouterListener.php on line 157

Since the (patched) Doctrine DBAL worked fine, I assumed it could provide a workaround.

It does.

@jrobeson I suspect that the issue you describe lies with HHVM returning a json array of defined "falsey" values, rather than an empty array for that operation. This, in turn, probably favors - or even causes the aforementioned session storage issue, but I stopped at having found an applicable workaround.

[fredemmott]

Commented on the HHVM issue - my guess is this difference of behavior:

<?php

$foo = new ArrayObject();
$foo[] = $foo;
var_dump(json_encode($foo));

http://3v4l.org/B11YU

[fredemmott]

We think this was fixed by https://github.com/facebook/hhvm/commit/faeab0be53b374c559e8ffe21f5489aa0fba2533

[fabpot]

@fredemmott Great! Thanks for the feedback. @Solar-Logos Whenever you can, would you test the fix referenced above? Thanks.

[TandFMachine]

Gladly @fabpot . Will confirm the fix within a few days, and thank you for Symfony and Silex. I enjoy both thoroughly (kindly note that I am accessing GitHub as ArgoNavis these days, both profiles belong to me).

[maurocolella]

Installed hhvm-nightly today, I set the session handler back to the default. Login state is not stored.

The output is more consistent:

[2014-09-27 06:24:04] myapp.INFO: Matched route "auth" (parameters: "_controller": "null", "_route": "auth") [] []
[2014-09-27 06:24:04] myapp.INFO: User "argo" has been authenticated successfully [] []
[2014-09-27 06:24:04] myapp.INFO: < 302 http://dev.mydomain.com/ [] []
[2014-09-27 06:24:04] myapp.DEBUG: Write SecurityContext in the session [] []
[2014-09-27 06:24:04] myapp.INFO: Matched route "GET_" (parameters: "_controller": "", "_route": "GET_") [] []
[2014-09-27 06:24:04] myapp.INFO: Populated SecurityContext with an anonymous Token [] []
[2014-09-27 06:24:04] myapp.INFO: > GET / [] []
[2014-09-27 06:24:04] myapp.INFO: < 200 [] []
[2014-09-27 06:24:04] myapp.DEBUG: Write SecurityContext in the session [] []

I then made sure hhvm has write privileges to the session save path (changed /etc/hhvm/php.ini, set the session save path to a folder owned by www-data, restarted the server): session files are stored.

I will gladly reproduce the content of session files. I see three main sections: _sf2_attributes, _sf2_flashes, and _sf2_meta.

Please advise.

[joshuataylor]

Having this exact issue with Symfony2, not sure where to crosspost to. PDO sessions fixed this.

[stephenmelrose]

On review, I think I'm having a similar problem, but probably caused by the same root issue. See the below logs,

[2015-02-18 17:15:00] myapp.INFO: Matched route "GET_login" (parameters: "_controller": "MyApp\Controller\LoginController::homeAction", "_route": "GET_login") [] []
[2015-02-18 17:15:00] myapp.INFO: > GET /login [] []
[2015-02-18 17:15:00] myapp.INFO: < 200 [] []
[2015-02-18 17:15:00] myapp.DEBUG: array (   0 => '.',   1 => '..',   2 => 'perf-7.map',   3 => 'sess_a806e2acddb4dc5a69753d0cd961d3f2', ) [] []

[2015-02-18 17:15:25] myapp.INFO: Matched route "login_check" (parameters: "_controller": "null", "_route": "login_check") [] []
[2015-02-18 17:15:25] myapp.DEBUG: Database query prepared {"statement":"SELECT `id`, `displayName`, `email`, `passwordHash`, `passwordSalt` FROM `user` WHERE `email` = ?"} []
[2015-02-18 17:15:25] myapp.INFO: Database query complete {"statement":"SELECT `id`, `displayName`, `email`, `passwordHash`, `passwordSalt` FROM `user` WHERE `email` = ?","parameters":["user@example.com"],"time":0.00035715103149414} []
[2015-02-18 17:15:25] myapp.INFO: User "user@example.com" has been authenticated successfully [] []
[2015-02-18 17:15:25] myapp.INFO: < 302 http://localhost:8080/ [] []
[2015-02-18 17:15:25] myapp.DEBUG: Write SecurityContext in the session [] []
[2015-02-18 17:15:25] myapp.DEBUG: array (   0 => '.',   1 => '..',   2 => 'perf-7.map', ) [] []

[2015-02-18 17:15:25] myapp.INFO: Matched route "GET_" (parameters: "_controller": "{}", "_route": "GET_") [] []
[2015-02-18 17:15:25] myapp.INFO: Authentication exception occurred; redirecting to authentication entry point (A Token was not found in the SecurityContext.) [] []
[2015-02-18 17:15:25] myapp.DEBUG: Calling Authentication entry point [] []
[2015-02-18 17:15:25] myapp.INFO: < 302 http://localhost:8080/login [] []
[2015-02-18 17:15:25] myapp.DEBUG: Write SecurityContext in the session [] []
[2015-02-18 17:15:25] myapp.DEBUG: array (   0 => '.',   1 => '..',   2 => 'perf-7.map',   3 => 'sess_f0b05b304e93dbdcdef1280736263ff7', ) [] []

[2015-02-18 17:15:25] myapp.INFO: Matched route "GET_login" (parameters: "_controller": "MyApp\Controller\LoginController::homeAction", "_route": "GET_login") [] []
[2015-02-18 17:15:25] myapp.INFO: > GET /login [] []
[2015-02-18 17:15:25] myapp.INFO: < 200 [] []
[2015-02-18 17:15:25] myapp.DEBUG: array (   0 => '.',   1 => '..',   2 => 'perf-7.map',   3 => 'sess_f0b05b304e93dbdcdef1280736263ff7', ) [] []

The initial request is for the login screen. The last line is var_export(scandir('/tmp'), true). As you can see, there's a session file (I'm using file based sessions, but I also get this problem with redis based sessions).

The second request is the login request. The user is successfully authenticated, and the SecurityContext is written to the session. This is where problems seem to begin. The session file is now gone, which you'd expect if the session ID was regenerated. But importantly, there are no session files.

On the third request, the expected SecurityContext was not found, which matches up if the session file isn't present. A new session is generated, and a session file exists at the end.

The fourth and last request is back to the login screen.

I'm using the following,

hhvm 3.5.0
silex/silex v1.2.3
symfony/security v2.6.4

Also, this is my security setup,

$app->register(new SecurityServiceProvider(), [
    'security.firewalls' => [
        'login' => [
            'pattern' => '^/login$'
        ],
        'app' => [
            'pattern' => '^.*$',
            'form' => ['login_path' => '/login', 'check_path' => '/login/check'],
            'logout' => ['logout_path' => '/logout'],
            'users' => $app->share(function ($app) {
                return new UserProvider($app['user.repository']);
            })
        ]
    ]
]);

Any ideas?

[davedevelopment]

@stephenmelrose tried throwing a $app['session']->save() in before your debug logging the scandir? Just wanted to rule out the session not being written by then?

[stephenmelrose]

@davedevelopment I didn't, no. Nuked the hacking I'd done. I'll give it another go tomorrow.

[digitalkaoz]

same problem here but with symfony and hhvm3.5.

i can confirm that PDO fixed it for me. it neither worked with snc-redis or file :/

[vguardiola]

The same problem tested with HHVM 3.5 and 3.6.1, my session configuration is with the redis handler.

I test to do a session_start on app.php before kernel start and it works properly, I think is a symfony problem or a bad session configuration

I see that exist some difference between session on php and hhvm when the browser load registration/confirmed/ PHP:

array (size=3)
  '_sf2_attributes' => &
    array (size=1)
      '_security_mainreg' => string 'C:74:"Symfony\Component\Security\Core\Authentication\Token\UsernamePasswordToken":707:... (length=795)
  '_sf2_flashes' => &
    array (size=0)
      empty
  '_sf2_meta' => &
    array (size=3)
      'u' => int 1428919484
      'c' => int 1428919484
      'l' => string '0' (length=1)

HHVM:

Array
(
    [_sf2_attributes] => Array
        (
        )
    [_sf2_flashes] => Array
        (
        )
    [_sf2_meta] => Array
        (
            [u] => 1428920356
            [c] => 1428920356
            [l] => 0
        )
)

I follow the code and stop (die) it when ContextListener save the token to the session and it work properly an in my redis the session is correct.

Some idea?

[wojtas]

Same problem here with HHVM 3.7.1 and Symfony 2.3.28. File session storage doesn't work with HHVM and Symfony2, although in my legacy app admin panel, where I handle sessions by myself, everything is handled correctly. So it seems to be related to the session persistence implementation in Symfonyas @vguardiola suggests, rather than a general HHVM bug, or so I think.

When I have some more time I'll try to delve into the problem.

[StyxOfDynamite]

http://labs.qandidate.com/blog/2013/10/21/running-symfony-standard-on-hhvm/

Suggests the issues is with symfony2 on HHVM.

[maurocolella]

There is no "suggesting".

The same core code functions differently on HHVM and PHP. The only thing to add to this bug report is a test case, as opposed to needless static.

On Wed, Jun 24, 2015 at 8:54 PM, Luke Storer notifications@github.com wrote:

http://labs.qandidate.com/blog/2013/10/21/running-symfony-standard-on-hhvm/

Suggests the issues is with symfony2 on HHVM.

— Reply to this email directly or view it on GitHub https://github.com/silexphp/Silex/issues/992#issuecomment-114859617.

[MblKiTA]

hhvm 3.8.0 fixed this issue for me

[fabpot]

@MblKiTA Thanks for the feedback, that's very interesting. Were you able to spot from the changelog which change(s) make this work on 3.8.0?

[MblKiTA]

@fabpot no, I just checked that authentication works with hhvm 3.8.0 and session file is created with user data in it:

_sf2_attributes|a:1:{s:15:"_security_admin";s:941:"C:74:"Symfony\Component\Security\Core\Authentication\Token\UsernamePasswordToken":853:{a:3:{i:0;N;i:1;s:5:"admin";i:2;s:812:"a:4:{i:0;O:41:"Symfony\Component\Security\Core\User\User":7:{s:51:"^@Symfony\Component\Security\Core\User\User^@username";s:5:"admin";s:51:"^@Symfony\Component\Security\Core\User\User^@password";s:88:"5FZ2Z8QIkA7UTZ4BYkoC+GsReLf569mSKDsfods6LYQ8t+a8EW9oaircfMpmaLbPBh4FOBiiFyLfuZmTSUwzZg==";s:50:"^@Symfony\Component\Security\Core\User\User^@enabled";b:1;s:60:"^@Symfony\Component\Security\Core\User\User^@accountNonExpired";b:1;s:64:"^@Symfony\Component\Security\Core\User\User^@credentialsNonExpired";b:1;s:59:"^@Symfony\Component\Security\Core\User\User^@accountNonLocked";b:1;s:48:"^@Symfony\Component\Security\Core\User\User^@roles";a:1:{i:0;s:10:"ROLE_ADMIN";}}i:1;b:1;i:2;a:1:{i:0;O:41:"Symfony\Component\Security\Core\Role\Role":1:{s:47:"^@Symfony\Component\Security\Core\Role\Role^@role";s:10:"ROLE_ADMIN";}}i:3;a:0:{}}";}}";}_sf2_flashes|a:0:{}_sf2_meta|a:3:{s:1:"u";i:1437340297;s:1:"c";i:1437340297;s:1:"l";s:1:"0";}

[digitalkaoz]

for me this fixed it: https://github.com/snc/SncRedisBundle/commit/6d513735ec0465013ec51b191e21894f057eb683

[fabpot]

Closing as it apparently works for HHVM 3.8 and the redis bundle was also fixed.