New Session is started on each request #38964

bastoune · 2020-11-02T15:13:20Z

Symfony version(s) affected: 4.4.16

Having an app running perfectly on my local with docker.

When I deploy it, I can't get why a new session is started on each request. It seems it can't come from the code since it's exactly the same.

The session is stored on a redis DB (I have the same bug if I use the filesystem session). It's there I can see all the new session created. (see last code block).

From the log I can clearly identify that the $request->getSession()->getId() changes on each request but not the PHPSESSID cookie.

For example:

First request

[2020-11-02 15:03:59] request.INFO: Matched route "app_login". {"route":"app_login","route_parameters":{"_route":"app_login","_controller":"App\\Controller\\SecurityController::login"},"request_uri":"https://foo.bar.dev/login","method":"POST"} []
[2020-11-02 15:03:59] security.DEBUG: Checking for guard authentication credentials. {"firewall_key":"main","authenticators":1} []
[2020-11-02 15:03:59] security.DEBUG: Checking support on guard authenticator. {"firewall_key":"main","authenticator":"App\\Security\\LoginFormAuthenticator"} []
[2020-11-02 15:03:59] app.DEBUG: [LoginFormAuthenticator::supports] $request session id => 6491ddf4e8f3e2eaa22b44b3a98c094a [] []
[2020-11-02 15:03:59] app.DEBUG: [LoginFormAuthenticator::supports] $_COOKIE =>  {"PHPSESSID":"87cf6185b652f8d713c45031ebe6d8a4"} []

Second one

[2020-11-02 15:04:33] request.INFO: Matched route "app_login". {"route":"app_login","route_parameters":{"_route":"app_login","_controller":"App\\Controller\\SecurityController::login"},"request_uri":"https://foo.bar.dev/login","method":"POST"} []
[2020-11-02 15:04:33] security.DEBUG: Checking for guard authentication credentials. {"firewall_key":"main","authenticators":1} []
[2020-11-02 15:04:33] security.DEBUG: Checking support on guard authenticator. {"firewall_key":"main","authenticator":"App\\Security\\LoginFormAuthenticator"} []
[2020-11-02 15:04:33] app.DEBUG: [LoginFormAuthenticator::supports] $request session id => 41b08dac8a803337a48dca7d5b33b840 [] []
[2020-11-02 15:04:33] app.DEBUG: [LoginFormAuthenticator::supports] $_COOKIE =>  {"PHPSESSID":"87cf6185b652f8d713c45031ebe6d8a4"} []

KUBERNETES

ingress-nginx.yaml

apiVersion: networking.k8s.io/v1beta1
kind: Ingress
metadata:
  name: secured-front
  namespace: foo-apis-dev
  annotations:
    kubernetes.io/ingress.class: nginx
    cert-manager.io/cluster-issuer: letsencrypt-prod
    nginx.ingress.kubernetes.io/rewrite-target: /$1
    nginx.ingress.kubernetes.io/use-regex: "true"
    nginx.ingress.kubernetes.io/affinity: "cookie"
    nginx.ingress.kubernetes.io/affinity-mode: "persistent"
    nginx.ingress.kubernetes.io/session-cookie-name: "PHPSESSID"
    nginx.ingress.kubernetes.io/session-cookie-path: "/(.*)"
    nginx.ingress.kubernetes.io/session-cookie-samesite: "Lax"
    nginx.ingress.kubernetes.io/session-cookie-expires: "172800000"
    nginx.ingress.kubernetes.io/session-cookie-max-age: "172800000"
spec:
  tls:
    - hosts:
        - bar.foo.dev
      secretName: tls-secret
  rules:
    - host: bar.foo.dev
      http:
        paths:
          - backend:
              serviceName: bar-nginx
              servicePort: 80
            path: /(.*)

Symfony APP

services.yaml

[...]
    Redis:
        class: Redis
        calls:
            - connect:
                  - '%env(REDIS_HOST)%'
                  - '%env(int:REDIS_PORT)%'

    Symfony\Component\HttpFoundation\Session\Storage\Handler\RedisSessionHandler:
        arguments:
            - '@Redis'
            - { prefix: 'admin_phpsess_' }
[...]

packages.framework.yaml

[...]
    session:
        handler_id: Symfony\Component\HttpFoundation\Session\Storage\Handler\RedisSessionHandler
        cookie_secure: auto
        cookie_samesite: lax
[...]

REDIS

127.0.0.1:6379> KEYS *admin*
1) "admin_phpsess_245e4a79fe35e2320943770061884c24"
2) "admin_phpsess_0ff29464322b3c2cfc5d8f5fd323ef75"
3) "admin_phpsess_26812c17f93a5d28a71853b77ac85386"
4) "admin_phpsess_7fbae6f0b1fdbe9576e41c9eee2cd60f"

VERSIONS:

PHP 7.4.12
Symfony 4.4
Kubernetes 1.17.9
redis (pecl) 5.3.2

The text was updated successfully, but these errors were encountered:

nicolas-grekas · 2020-11-02T15:23:59Z

Fixed by #38910?
/cc @jderusse

bastoune · 2020-11-02T15:29:09Z

@nicolas-grekas @jderusse

How could I help you know if it's related ?
How could I apply a TMP fix before a new release ?

jderusse · 2020-11-02T15:29:38Z

Fixed by #38910?
/cc @jderusse

Hmm, I don't think it's related. This PR, prevent initializing the session_storage twice which does not have side effect for end user.

I think the issue is more related to the log Checking for guard authentication credentials

With 5.2 you can check in profiler what started the session, in previous version, I use \debug_print_backtrace(2);die; in NativeSessionStorage::start() method

bastoune · 2020-11-03T09:39:48Z

The issue was about the redis configuration.
I took the step of using PdoSessionHandler and it works.
The problem comes from Redis and / or Kubernetes, I have been trying for 2 hours to point out the configuration which generates this bug but impossible for now.

dkarlovi · 2020-11-13T16:47:25Z

This happens to me with 5.1, if I set cookie_samesite: strict for some reason. If I omit it, it works. Is something like that known? What would be the way to debug this easiest? I can see the Cookie is in the request and a new Set-Cookie in the response.

It doesn't happen with cookie_samesite: lax or without it.

bastoune · 2020-11-16T14:14:14Z

I had cookie_samesite: lax and it happened.

David-Crty · 2020-11-16T14:41:53Z

I have exactly the same issue:
-> with or without Redis.
-> with or without cookie_samesite: lax

@bastoune first you say

The session is stored on a redis DB (I have the same bug if I use the filesystem session).

And then

The issue was about the redis configuration.

🤔

My auth system is done with lexik_jwt_authentication so not linked to Session
Symfony 4.4.15

jderusse · 2020-11-16T14:52:34Z

Could you please provide a reproducer?
Or put a \debug_print_backtrace(2);die; in the NativeSessionStorage::start method and provide the backtrace?

David-Crty · 2020-11-16T14:56:34Z

I have put \debug_print_backtrace(2);die; at the end of the function \Symfony\Component\HttpFoundation\Session\Storage\NativeSessionStorage::start
->

#1  Symfony\Component\HttpFoundation\Session\Storage\NativeSessionStorage->getBag() called at [/var/www/vendor/symfony/http-foundation/Session/Session.php:249]
#2  Symfony\Component\HttpFoundation\Session\Session->getBag() called at [/var/www/vendor/symfony/http-foundation/Session/Session.php:271]
#3  Symfony\Component\HttpFoundation\Session\Session->getAttributeBag() called at [/var/www/vendor/symfony/http-foundation/Session/Session.php:73]
#4  Symfony\Component\HttpFoundation\Session\Session->get() called at [/var/www/vendor/symfony/security/Http/Firewall/ContextListener.php:119]
#5  Symfony\Component\Security\Http\Firewall\ContextListener->authenticate() called at [/var/www/vendor/symfony/security-bundle/Debug/WrappedLazyListener.php:49]
#6  Symfony\Bundle\SecurityBundle\Debug\WrappedLazyListener->authenticate() called at [/var/www/vendor/symfony/security/Http/Firewall/AbstractListener.php:27]
#7  Symfony\Component\Security\Http\Firewall\AbstractListener->__invoke() called at [/var/www/vendor/symfony/security-bundle/Debug/TraceableFirewallListener.php:62]
#8  Symfony\Bundle\SecurityBundle\Debug\TraceableFirewallListener->callListeners() called at [/var/www/vendor/symfony/security/Http/Firewall.php:98]
#9  Symfony\Component\Security\Http\Firewall->onKernelRequest() called at [/var/www/vendor/symfony/event-dispatcher/Debug/WrappedListener.php:126]
#10 Symfony\Component\EventDispatcher\Debug\WrappedListener->__invoke() called at [/var/www/vendor/symfony/event-dispatcher/EventDispatcher.php:264]
#11 Symfony\Component\EventDispatcher\EventDispatcher->doDispatch() called at [/var/www/vendor/symfony/event-dispatcher/EventDispatcher.php:239]
#12 Symfony\Component\EventDispatcher\EventDispatcher->callListeners() called at [/var/www/vendor/symfony/event-dispatcher/EventDispatcher.php:73]
#13 Symfony\Component\EventDispatcher\EventDispatcher->dispatch() called at [/var/www/vendor/symfony/event-dispatcher/Debug/TraceableEventDispatcher.php:168]
#14 Symfony\Component\EventDispatcher\Debug\TraceableEventDispatcher->dispatch() called at [/var/www/vendor/symfony/http-kernel/HttpKernel.php:134]
#15 Symfony\Component\HttpKernel\HttpKernel->handleRaw() called at [/var/www/vendor/symfony/http-kernel/HttpKernel.php:80]
#16 Symfony\Component\HttpKernel\HttpKernel->handle() called at [/var/www/vendor/symfony/http-kernel/Kernel.php:201]
#17 Symfony\Component\HttpKernel\Kernel->handle() called at [/var/www/public/index.php:25]

jderusse · 2020-11-16T15:13:08Z

hmm.. In ContextListener.php at 114 it check if a previous session exists in the request and then start it at line 119.
Which mean, you already had a previous session. That's why the session is started here

David-Crty · 2020-11-16T15:58:29Z

I'm not sure to understand, can I help you more to debug this ?
Should I change something to fix the issue ?
I don't know if this can help you but here is a screenshot of phpstorm where the sessions is start() but shouldn't

Already thanks for looking into this issue

jderusse · 2020-11-16T17:14:19Z

I mean the session has been started in this request because the request sent a cookie with an existing session (which has been initialized in a previous request).

If you want to find what started the session previously, you have to clear your cookies (or open a private browsing tab) and retry the debug_print_backtrace(2) in

David-Crty · 2020-11-17T23:10:18Z

Okay my probleme is that my SessionAuthenticationStrategy is on migrate, probablie because of lexik_jwt_authentication.

Thanks for the help anyway !

bastoune · 2020-11-19T10:39:19Z

@David-Crty

I have exactly the same issue:
-> with or without Redis.
-> with or without cookie_samesite: lax

@bastoune first you say

The session is stored on a redis DB (I have the same bug if I use the filesystem session).

And then

The issue was about the redis configuration.

🤔

My auth system is done with lexik_jwt_authentication so not linked to Session
Symfony 4.4.15

Sorry for this,

The thing is that I solved it by changing the handler to a PdoSessionHandler so my guesses are :
-> The FS has similar issue due to the non persistency
-> The Redis config wasn't OK

I still have an unresolved internal ticket to find the origin.

bastoune added the Bug label Nov 2, 2020

carsonbot added the Status: Needs Review label Nov 2, 2020

xabbuh added the HttpFoundation label Nov 3, 2020

bastoune closed this as completed Nov 3, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

New Session is started on each request #38964

New Session is started on each request #38964

bastoune commented Nov 2, 2020

nicolas-grekas commented Nov 2, 2020

bastoune commented Nov 2, 2020

jderusse commented Nov 2, 2020

bastoune commented Nov 3, 2020

dkarlovi commented Nov 13, 2020 •

edited

Loading

bastoune commented Nov 16, 2020

David-Crty commented Nov 16, 2020

jderusse commented Nov 16, 2020

David-Crty commented Nov 16, 2020

jderusse commented Nov 16, 2020

David-Crty commented Nov 16, 2020 •

edited

Loading

jderusse commented Nov 16, 2020

David-Crty commented Nov 17, 2020

bastoune commented Nov 19, 2020 •

edited

Loading

New Session is started on each request #38964

New Session is started on each request #38964

Comments

bastoune commented Nov 2, 2020

nicolas-grekas commented Nov 2, 2020

bastoune commented Nov 2, 2020

jderusse commented Nov 2, 2020

bastoune commented Nov 3, 2020

dkarlovi commented Nov 13, 2020 • edited Loading

bastoune commented Nov 16, 2020

David-Crty commented Nov 16, 2020

jderusse commented Nov 16, 2020

David-Crty commented Nov 16, 2020

jderusse commented Nov 16, 2020

David-Crty commented Nov 16, 2020 • edited Loading

jderusse commented Nov 16, 2020

David-Crty commented Nov 17, 2020

bastoune commented Nov 19, 2020 • edited Loading

dkarlovi commented Nov 13, 2020 •

edited

Loading

David-Crty commented Nov 16, 2020 •

edited

Loading

bastoune commented Nov 19, 2020 •

edited

Loading