Uploaded image for project: 'eZ Publish / Platform'
  1. eZ Publish / Platform
  2. EZP-22910

Formtoken exception is thrown when logging in without debug redirection

    Details

      Description

      Logging in without debug and debug redirection will throw a fatal error

      Error in prod.log file

      [2014-05-22 16:51:35] security.DEBUG: Write SecurityContext in the session [] []
      [2014-05-22 16:51:51] app.INFO: Router eZ\Bundle\EzPublishCoreBundle\Routing\DefaultRouter was not able to match, message "" [] []
      [2014-05-22 16:51:51] app.INFO: Router eZ\Bundle\EzPublishCoreBundle\Routing\UrlAliasRouter was not able to match, message "Config says to bypass UrlAliasRouter" [] []
      [2014-05-22 16:51:51] request.INFO: Matched route "ez_legacy" (parameters: "_route": "ez_legacy", "_controller": "ezpublish_legacy.controller:indexAction") [] []
      [2014-05-22 16:51:51] security.INFO: Populated SecurityContext with an anonymous Token [] []
      [2014-05-22 16:51:51] app.DEBUG: Legacy kernel: Leaving '/var/www/html/ezpublish5/web' for '/var/www/html/ezpublish5/ezpublish/../ezpublish_legacy' [] []
      [2014-05-22 16:51:51] app.DEBUG: Legacy kernel: Leaving '/var/www/html/ezpublish5/ezpublish/../ezpublish_legacy' for '/var/www/html/ezpublish5/web' [] []
      [2014-05-22 16:51:51] app.DEBUG: Legacy kernel: Leaving '/var/www/html/ezpublish5/web' for '/var/www/html/ezpublish5/ezpublish/../ezpublish_legacy' [] []
      [2014-05-22 16:51:51] request.CRITICAL: Uncaught PHP Exception Exception: "Wrong form token found in Request!" at /var/www/html/ezpublish5/ezpublish_legacy/extension/ezformtoken/event/ezxformtoken.php line 152 {"exception":"[object] (Exception: Wrong form token found in Request! at /var/www/html/ezpublish5/ezpublish_legacy/extension/ezformtoken/event/ezxformtoken.php:152)"} []
      

        Issue Links

          Activity

          Joao Pingo (Inactive) created issue -
          Joao Pingo (Inactive) made changes -
          Field Original Value New Value
          Summary FormToken exception is trown when loggin in to admin withot debug redirection FormToken exception is trown when loggin in to admin interface withot debug redirection
          Joao Pingo (Inactive) made changes -
          Summary FormToken exception is trown when loggin in to admin interface withot debug redirection Formtoken exception is trown when loggin in to admin interface withot debug redirection
          Paulo Nunes (Inactive) made changes -
          Summary Formtoken exception is trown when loggin in to admin interface withot debug redirection Formtoken exception is trown when loggin in to admin interface without debug redirection
          Joao Pingo (Inactive) made changes -
          Summary Formtoken exception is trown when loggin in to admin interface without debug redirection Formtoken exception is thrown when loggin in to admin interface without debug redirection
          Joao Pingo (Inactive) made changes -
          Summary Formtoken exception is thrown when loggin in to admin interface without debug redirection Formtoken exception is thrown when logging in to admin interface without debug redirection
          Joao Pingo (Inactive) made changes -
          Summary Formtoken exception is thrown when logging in to admin interface without debug redirection Formtoken exception is thrown when logging in without debug redirection
          Joao Pingo (Inactive) made changes -
          Description Logging in to admin interface, without debug and debug redirection will throw a fatal error

          Error in prod.log file
          {code}
          [2014-05-22 16:51:35] security.DEBUG: Write SecurityContext in the session [] []
          [2014-05-22 16:51:51] app.INFO: Router eZ\Bundle\EzPublishCoreBundle\Routing\DefaultRouter was not able to match, message "" [] []
          [2014-05-22 16:51:51] app.INFO: Router eZ\Bundle\EzPublishCoreBundle\Routing\UrlAliasRouter was not able to match, message "Config says to bypass UrlAliasRouter" [] []
          [2014-05-22 16:51:51] request.INFO: Matched route "ez_legacy" (parameters: "_route": "ez_legacy", "_controller": "ezpublish_legacy.controller:indexAction") [] []
          [2014-05-22 16:51:51] security.INFO: Populated SecurityContext with an anonymous Token [] []
          [2014-05-22 16:51:51] app.DEBUG: Legacy kernel: Leaving '/var/www/html/ezpublish5/web' for '/var/www/html/ezpublish5/ezpublish/../ezpublish_legacy' [] []
          [2014-05-22 16:51:51] app.DEBUG: Legacy kernel: Leaving '/var/www/html/ezpublish5/ezpublish/../ezpublish_legacy' for '/var/www/html/ezpublish5/web' [] []
          [2014-05-22 16:51:51] app.DEBUG: Legacy kernel: Leaving '/var/www/html/ezpublish5/web' for '/var/www/html/ezpublish5/ezpublish/../ezpublish_legacy' [] []
          [2014-05-22 16:51:51] request.CRITICAL: Uncaught PHP Exception Exception: "Wrong form token found in Request!" at /var/www/html/ezpublish5/ezpublish_legacy/extension/ezformtoken/event/ezxformtoken.php line 152 {"exception":"[object] (Exception: Wrong form token found in Request! at /var/www/html/ezpublish5/ezpublish_legacy/extension/ezformtoken/event/ezxformtoken.php:152)"} []
          {code}
          Logging in without debug and debug redirection will throw a fatal error

          Error in prod.log file
          {code}
          [2014-05-22 16:51:35] security.DEBUG: Write SecurityContext in the session [] []
          [2014-05-22 16:51:51] app.INFO: Router eZ\Bundle\EzPublishCoreBundle\Routing\DefaultRouter was not able to match, message "" [] []
          [2014-05-22 16:51:51] app.INFO: Router eZ\Bundle\EzPublishCoreBundle\Routing\UrlAliasRouter was not able to match, message "Config says to bypass UrlAliasRouter" [] []
          [2014-05-22 16:51:51] request.INFO: Matched route "ez_legacy" (parameters: "_route": "ez_legacy", "_controller": "ezpublish_legacy.controller:indexAction") [] []
          [2014-05-22 16:51:51] security.INFO: Populated SecurityContext with an anonymous Token [] []
          [2014-05-22 16:51:51] app.DEBUG: Legacy kernel: Leaving '/var/www/html/ezpublish5/web' for '/var/www/html/ezpublish5/ezpublish/../ezpublish_legacy' [] []
          [2014-05-22 16:51:51] app.DEBUG: Legacy kernel: Leaving '/var/www/html/ezpublish5/ezpublish/../ezpublish_legacy' for '/var/www/html/ezpublish5/web' [] []
          [2014-05-22 16:51:51] app.DEBUG: Legacy kernel: Leaving '/var/www/html/ezpublish5/web' for '/var/www/html/ezpublish5/ezpublish/../ezpublish_legacy' [] []
          [2014-05-22 16:51:51] request.CRITICAL: Uncaught PHP Exception Exception: "Wrong form token found in Request!" at /var/www/html/ezpublish5/ezpublish_legacy/extension/ezformtoken/event/ezxformtoken.php line 152 {"exception":"[object] (Exception: Wrong form token found in Request! at /var/www/html/ezpublish5/ezpublish_legacy/extension/ezformtoken/event/ezxformtoken.php:152)"} []
          {code}
          André Rømcke made changes -
          Status Open [ 1 ] Confirmed [ 10037 ]
          André Rømcke made changes -
          Status Confirmed [ 10037 ] InputQ [ 10001 ]
          Hide
          André Rømcke added a comment -

          I got the same thing yesterday, but after refresh (probably after enabling debugRedirection) it went away and I was already logged in.

          Show
          André Rømcke added a comment - I got the same thing yesterday, but after refresh (probably after enabling debugRedirection) it went away and I was already logged in.
          Hide
          Joao Pingo (Inactive) added a comment -

          We have the same behavior ...

          1. Login
          2. The error is shown
          3. Open admin site access
          4. You are correctly logged in
          Show
          Joao Pingo (Inactive) added a comment - We have the same behavior ... Login The error is shown Open admin site access You are correctly logged in
          Hide
          Pedro Resende (Inactive) added a comment -

          I've tested this with Debian 7 + Postgres and apparently the issue isn't present.

          Show
          Pedro Resende (Inactive) added a comment - I've tested this with Debian 7 + Postgres and apparently the issue isn't present.
          Hide
          Paulo Nunes (Inactive) added a comment -

          In my PostgreSQL debian, the issue also happened a couple of times

          Show
          Paulo Nunes (Inactive) added a comment - In my PostgreSQL debian, the issue also happened a couple of times
          André Rømcke made changes -
          Rank Ranked higher
          Hide
          André Rømcke added a comment -

          [1] Exception: Missing form token from Request
              at n/a
                  in /var/www/html/ezpublish5/ezpublish_legacy/extension/ezformtoken/event/ezxformtoken.php line 148
           
              at ezxFormToken::input(object(eZURI))
                  in  line 
           
              at call_user_func_array(array('ezxFormToken', 'input'), array(object(eZURI)))
                  in /var/www/html/ezpublish5/ezpublish_legacy/kernel/private/classes/ezpevent.php line 138
           
              at ezpEvent->notify('request/input', array(object(eZURI)))
                  in /var/www/html/ezpublish5/ezpublish_legacy/kernel/private/classes/ezpkernelweb.php line 1162
           
              at ezpKernelWeb->requestInit()
                  in /var/www/html/ezpublish5/ezpublish_legacy/kernel/private/classes/ezpkernelweb.php line 310
           
              at ezpKernelWeb->run()
                  in /var/www/html/ezpublish5/ezpublish_legacy/kernel/private/classes/ezpkernel.php line 53
           
              at ezpKernel->run()
                  in /var/www/html/ezpublish5/vendor/ezsystems/ezpublish-kernel/eZ/Publish/Core/MVC/Legacy/Kernel.php line 132
           
              at eZ\Publish\Core\MVC\Legacy\Kernel->run()
                  in /var/www/html/ezpublish5/vendor/ezsystems/ezpublish-kernel/eZ/Bundle/EzPublishLegacyBundle/Controller/LegacyKernelController.php line 99
           
              at eZ\Bundle\EzPublishLegacyBundle\Controller\LegacyKernelController->indexAction()
                  in  line 
           
              at call_user_func_array(array(object(LegacyKernelController), 'indexAction'), array())
                  in /var/www/html/ezpublish5/vendor/symfony/symfony/src/Symfony/Component/HttpKernel/HttpKernel.php line 117
           
              at Symfony\Component\HttpKernel\HttpKernel->handleRaw(object(Request), '1')
                  in /var/www/html/ezpublish5/vendor/symfony/symfony/src/Symfony/Component/HttpKernel/HttpKernel.php line 61
           
              at Symfony\Component\HttpKernel\HttpKernel->handle(object(Request), '1', true)
                  in /var/www/html/ezpublish5/vendor/symfony/symfony/src/Symfony/Component/HttpKernel/DependencyInjection/ContainerAwareHttpKernel.php line 62
           
              at Symfony\Component\HttpKernel\DependencyInjection\ContainerAwareHttpKernel->handle(object(Request), '1', true)
                  in /var/www/html/ezpublish5/vendor/symfony/symfony/src/Symfony/Component/HttpKernel/Kernel.php line 187
           
              at Symfony\Component\HttpKernel\Kernel->handle(object(Request), '1', true)
                  in /var/www/html/ezpublish5/vendor/ezsystems/ezpublish-kernel/eZ/Bundle/EzPublishCoreBundle/Kernel.php line 67
           
              at eZ\Bundle\EzPublishCoreBundle\Kernel->handle(object(Request))
                  in /var/www/html/ezpublish5/web/index.php line 77

          I think I understand what is going on now, the new login functionality is causing a redirect that is causing form data to be forwarded causing formtoken check to fail, and this seem to be avoided on debug redirection.

          Show
          André Rømcke added a comment - [1] Exception: Missing form token from Request at n/a in /var/www/html/ezpublish5/ezpublish_legacy/extension/ezformtoken/event/ezxformtoken.php line 148   at ezxFormToken::input(object(eZURI)) in line   at call_user_func_array(array('ezxFormToken', 'input'), array(object(eZURI))) in /var/www/html/ezpublish5/ezpublish_legacy/kernel/private/classes/ezpevent.php line 138   at ezpEvent->notify('request/input', array(object(eZURI))) in /var/www/html/ezpublish5/ezpublish_legacy/kernel/private/classes/ezpkernelweb.php line 1162   at ezpKernelWeb->requestInit() in /var/www/html/ezpublish5/ezpublish_legacy/kernel/private/classes/ezpkernelweb.php line 310   at ezpKernelWeb->run() in /var/www/html/ezpublish5/ezpublish_legacy/kernel/private/classes/ezpkernel.php line 53   at ezpKernel->run() in /var/www/html/ezpublish5/vendor/ezsystems/ezpublish-kernel/eZ/Publish/Core/MVC/Legacy/Kernel.php line 132   at eZ\Publish\Core\MVC\Legacy\Kernel->run() in /var/www/html/ezpublish5/vendor/ezsystems/ezpublish-kernel/eZ/Bundle/EzPublishLegacyBundle/Controller/LegacyKernelController.php line 99   at eZ\Bundle\EzPublishLegacyBundle\Controller\LegacyKernelController->indexAction() in line   at call_user_func_array(array(object(LegacyKernelController), 'indexAction'), array()) in /var/www/html/ezpublish5/vendor/symfony/symfony/src/Symfony/Component/HttpKernel/HttpKernel.php line 117   at Symfony\Component\HttpKernel\HttpKernel->handleRaw(object(Request), '1') in /var/www/html/ezpublish5/vendor/symfony/symfony/src/Symfony/Component/HttpKernel/HttpKernel.php line 61   at Symfony\Component\HttpKernel\HttpKernel->handle(object(Request), '1', true) in /var/www/html/ezpublish5/vendor/symfony/symfony/src/Symfony/Component/HttpKernel/DependencyInjection/ContainerAwareHttpKernel.php line 62   at Symfony\Component\HttpKernel\DependencyInjection\ContainerAwareHttpKernel->handle(object(Request), '1', true) in /var/www/html/ezpublish5/vendor/symfony/symfony/src/Symfony/Component/HttpKernel/Kernel.php line 187   at Symfony\Component\HttpKernel\Kernel->handle(object(Request), '1', true) in /var/www/html/ezpublish5/vendor/ezsystems/ezpublish-kernel/eZ/Bundle/EzPublishCoreBundle/Kernel.php line 67   at eZ\Bundle\EzPublishCoreBundle\Kernel->handle(object(Request)) in /var/www/html/ezpublish5/web/index.php line 77 I think I understand what is going on now, the new login functionality is causing a redirect that is causing form data to be forwarded causing formtoken check to fail, and this seem to be avoided on debug redirection.
          Hide
          Jérôme Vieilledent (Inactive) added a comment -

          Regression from EZP-22767 . LegacyHelper is filled even if the result is an ezpKernelRedirect, triggering a form token exception when request is POST.
          Makes sense since LegacyHelper uses runCallback() which in this case re-triggers request parsing by the legacy kernel. As request is POST, it legitimately looks for the form token.

          For some reason, the issue does not happen with XDebug on.

          Show
          Jérôme Vieilledent (Inactive) added a comment - Regression from EZP-22767 . LegacyHelper is filled even if the result is an ezpKernelRedirect , triggering a form token exception when request is POST. Makes sense since LegacyHelper uses runCallback() which in this case re-triggers request parsing by the legacy kernel. As request is POST, it legitimately looks for the form token. For some reason, the issue does not happen with XDebug on.
          Jérôme Vieilledent (Inactive) made changes -
          Link This issue relates to EZP-22767 [ EZP-22767 ]
          Jérôme Vieilledent (Inactive) made changes -
          Status InputQ [ 10001 ] Development [ 3 ]
          Assignee Jérôme Vieilledent [ jerome.vieilledent@ez.no ]
          Show
          Jérôme Vieilledent (Inactive) added a comment - See comment on the commit that caused the regression .
          Jérôme Vieilledent (Inactive) made changes -
          Status Development [ 3 ] Development review [ 10006 ]
          Affects Version/s 2014.05 [ 13480 ]
          Fix Version/s 5.3 [ 11282 ]
          Show
          Jérôme Vieilledent (Inactive) added a comment - PR: https://github.com/ezsystems/ezpublish-kernel/pull/875
          Jérôme Vieilledent (Inactive) made changes -
          Remote Link This issue links to "PR (Web Link)" [ 14088 ]
          Show
          Jérôme Vieilledent (Inactive) added a comment - Fixed in master: https://github.com/ezsystems/ezpublish-kernel/commit/4467532c4703317d55b82303c990c7559c9eaa28
          Jérôme Vieilledent (Inactive) made changes -
          Status Development review [ 10006 ] Development Review done [ 10028 ]
          Jérôme Vieilledent (Inactive) made changes -
          Status Development Review done [ 10028 ] Documentation done [ 10011 ]
          Paulo Nunes (Inactive) made changes -
          Status Documentation done [ 10011 ] QA [ 10008 ]
          Assignee Jérôme Vieilledent [ jerome.vieilledent@ez.no ] Paulo Nunes [ paulo.nunes@ez.no ]
          Hide
          Paulo Nunes (Inactive) added a comment -

          QA Approved

          Show
          Paulo Nunes (Inactive) added a comment - QA Approved
          Paulo Nunes (Inactive) made changes -
          Assignee Paulo Nunes [ paulo.nunes@ez.no ]
          Status QA [ 10008 ] Closed [ 6 ]
          Resolution Fixed [ 1 ]
          André Rømcke made changes -
          Workflow eZ Engineering Scrumban Workflow [ 63347 ] EZ* Development Workflow [ 85068 ]
          Alex Schuster made changes -
          Workflow EZ* Development Workflow [ 85068 ] EZEE Development Workflow [ 123846 ]
          Transition Time In Source Status Execution Times Last Executer Last Execution Date
          Open Open Confirmed Confirmed
          13m 49s 1 André Rømcke 22/May/14 5:14 PM
          Confirmed Confirmed InputQ InputQ
          2s 1 André Rømcke 22/May/14 5:14 PM
          InputQ InputQ Development Development
          3d 20h 32m 1 jerome.vieilledent@ez.no 26/May/14 1:47 PM
          Development Development Development Review Development Review
          5m 15s 1 jerome.vieilledent@ez.no 26/May/14 1:52 PM
          Development Review Development Review Development Review done Development Review done
          22m 9s 1 jerome.vieilledent@ez.no 26/May/14 2:14 PM
          Development Review done Development Review done Documentation Review done Documentation Review done
          51s 1 jerome.vieilledent@ez.no 26/May/14 2:15 PM
          Documentation Review done Documentation Review done QA QA
          1d 1h 43m 1 Paulo Nunes 27/May/14 3:59 PM
          QA QA Closed Closed
          32s 1 Paulo Nunes 27/May/14 3:59 PM

            People

            • Assignee:
              Unassigned
              Reporter:
              Joao Pingo (Inactive)
            • Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: