Bug #56348

Session randomly lost in eID

Added by Grégory Duchesnes over 8 years ago. Updated almost 7 years ago.

Status:
Closed
Priority:
Must have
Category:
Frontend
Target version:
-
Start date:
2014-02-26
Due date:
% Done:

0%

Estimated time:
TYPO3 Version:
6.1
PHP Version:
5.3
Tags:
Complexity:
hard
Is Regression:
No
Sprint Focus:

Description

Hi all,

I have a piece of eID code that checks if a user is loggued in to the website and then takes action or send him back to an error page.
Once in a while $GLOBALS["TSFE"]->fe_user->user is false for no reason (i can see in the logs that the user logged-in few only a few seconds before).

Bug occurs in any browser, the website runs in https, has a P3P policy (for IE) and is not behind a proxy.

Here is my code (simplified) :

$GLOBALS["TSFE"] = \TYPO3\CMS\Core\Utility\GeneralUtility::makeInstance('TYPO3\CMS\Frontend\Controller\TypoScriptFrontendController', $TYPO3_CONF_VARS, 0, 0);
$GLOBALS["TSFE"]->initFEuser();
if(!$GLOBALS["TSFE"]->fe_user->user) {
header('Location: /?logintype=logout&session=expired');
die();
}

My session config :

'FE' => array(
'lifetime' => '1800',
'loginSecurityLevel' => 'normal',
'permalogin' => '2',
'sessionDataLifetime' => '1800',
),

And here is what i see in my apache log file :

# the guy connects to the site : ok
xxx.51.48.xx - - [26/Feb/2014:10:40:01 +0100] "POST / HTTP/1.1" 200 17025
# downloads some resources : ok
xxx.51.48.xx - - [26/Feb/2014:10:40:03 +0100] "GET /typo3temp/vhs-assets-1f45c81006146c4e25a69b3c56b0fc5c-4e0ef181f23cb080794861bbc21114e0.css?1393407602 HTTP/1.1" 200 9520
# browses to another page : ok
xxx.51.48.xx - - [26/Feb/2014:10:40:52 +0100] "GET /attestations/ HTTP/1.1" 200 17037
# tries to call the eID : KO
xxx.51.48.xx - - [26/Feb/2014:10:41:02 +0100] "GET /attestations/?eID=espacesante_downloadAttestationSecu&annee=2013&fe_user=xxxxx&cHash=544421d45e7e2c1f2d9cc4d8896f4670 HTTP/1.1" 302 -
xxx.51.48.xx - - [26/Feb/2014:10:41:02 +0100] "GET /?logintype=logout&session=expired HTTP/1.1" 200 14851

And in my MySQL logs :

when everything works fine (goes to another page) :

140226 10:40:52   117 Connect    xxx@localhost on 
          117 Query    SET NAMES utf8
          117 Query    SELECT @@SESSION.sql_mode
          117 Init DB    xxx
          117 Query    SELECT COUNT(*) FROM fe_sessions WHERE ses_id = 'e5d1676ea7103abfcae1789cbc7dde18'
          117 Query    SELECT * FROM fe_sessions,fe_users WHERE fe_sessions.ses_id = 'e5d1676ea7103abfcae1789cbc7dde18'
                    AND fe_sessions.ses_name = 'fe_typo_user'
                    AND fe_sessions.ses_userid = fe_users.uid
                    AND (
                fe_sessions.ses_iplock = 'xxx.51'
                OR fe_sessions.ses_iplock='[DISABLED]'
                )
                    AND fe_sessions.ses_hashlock=59869828
                     AND fe_users.disable=0 AND fe_users.deleted=0 AND (fe_users.starttime<=1393407652) AND (fe_users.endtime=0 OR fe_users.endtime>1393407652)
          117 Query    UPDATE fe_sessions SET ses_tstamp='1393407652' WHERE ses_id='e5d1676ea7103abfcae1789cbc7dde18'
                                                AND ses_name='fe_typo_user'
          117 Query    SELECT * FROM fe_sessions,fe_users WHERE fe_sessions.ses_id = 'e5d1676ea7103abfcae1789cbc7dde18'
                    AND fe_sessions.ses_name = 'fe_typo_user'
                    AND fe_sessions.ses_userid = fe_users.uid
                    AND (
                fe_sessions.ses_iplock = 'xxx.51'
                OR fe_sessions.ses_iplock='[DISABLED]'
                )
                    AND fe_sessions.ses_hashlock=59869828
                     AND fe_users.disable=0 AND fe_users.deleted=0 AND (fe_users.starttime<=1393407652) AND (fe_users.endtime=0 OR fe_users.endtime>1393407652)
          117 Query    UPDATE fe_sessions SET ses_tstamp='1393407652' WHERE ses_id='e5d1676ea7103abfcae1789cbc7dde18'
                                                AND ses_name='fe_typo_user'
          117 Query    SELECT * FROM fe_session_data WHERE hash = 'e5d1676ea7103abfcae1789cbc7dde18'

And when it fails (eID) :

140226 10:41:02      132 Connect    xxx@localhost on 
          132 Query    SET NAMES utf8
          132 Query    SELECT @@SESSION.sql_mode
          132 Init DB    xxx
          132 Query    SELECT COUNT(*) FROM fe_sessions WHERE ses_id = 'e5d1676ea7103abfcae1789cbc7dde18'
          132 Query    SELECT content,tstamp FROM fe_session_data WHERE hash = 'e5d1676ea7103abfcae1789cbc7dde18'
          132 Query    SELECT * FROM fe_sessions,fe_users WHERE fe_sessions.ses_id = 'e5d1676ea7103abfcae1789cbc7dde18'
                    AND fe_sessions.ses_name = 'fe_typo_user'
                    AND fe_sessions.ses_userid = fe_users.uid

                    AND fe_sessions.ses_hashlock=59869828
                     AND fe_users.disable=0 AND fe_users.deleted=0 AND (fe_users.starttime<=1393407662) AND (fe_users.endtime=0 OR fe_users.endtime>1393407662)
          131 Query    SELECT content FROM cf_extbase_object WHERE identifier = 'f4161c7b5ff989cc5937476177f76d76' AND cf_extbase_object.expires >= 1393407661 LIMIT 1
          132 Query    SELECT /*! SQL_NO_CACHE */ ses_userid FROM fe_sessions WHERE ses_id=0
          132 Query    DELETE FROM fe_session_data WHERE hash='e5d1676ea7103abfcae1789cbc7dde18'
          132 Query    DELETE FROM fe_sessions WHERE ses_id = 'e5d1676ea7103abfcae1789cbc7dde18'
                        AND ses_name = 'fe_typo_user'
          132 Query    SELECT * FROM fe_sessions,fe_users WHERE fe_sessions.ses_id = 'e5d1676ea7103abfcae1789cbc7dde18'
                    AND fe_sessions.ses_name = 'fe_typo_user'
                    AND fe_sessions.ses_userid = fe_users.uid

                    AND fe_sessions.ses_hashlock=59869828
                     AND fe_users.disable=0 AND fe_users.deleted=0 AND (fe_users.starttime<=1393407662) AND (fe_users.endtime=0 OR fe_users.endtime>1393407662)
          132 Query    SELECT /*! SQL_NO_CACHE */ ses_userid FROM fe_sessions WHERE ses_id=0
          132 Query    DELETE FROM fe_session_data WHERE hash='e5d1676ea7103abfcae1789cbc7dde18'
          132 Query    DELETE FROM fe_sessions WHERE ses_id = 'e5d1676ea7103abfcae1789cbc7dde18'
                        AND ses_name = 'fe_typo_user'
          132 Quit

Any clue?


Related issues

Related to TYPO3 Core - Bug #53598: Select/Delete fe_sessions twice per requestClosedAlexander Opitz2013-11-13

Actions
#1

Updated by Grégory Duchesnes over 8 years ago

NB : bug is not garbage collector related since session garbage collection occured at 10:39:22 (before the initial login) and at 10:42:21 (after error)

#2

Updated by Markus Klein over 8 years ago

Where does the line
132 SELECT /*! SQL_NO_CACHE */ ses_userid FROM fe_sessions WHERE ses_id=0
come from?

(The whole 6.1 Core does contain the string "SQL_NO_CACHE" only once. And that is in a unit test for DBAL extension)

Furthermore I can recommend a look into \TYPO3\CMS\Frontend\Utility\EidUtility which provides some nice helper functions here.
Your example would reduce to:

$feuser = \TYPO3\CMS\Frontend\Utility\EidUtility:initFeUser();
if (empty($feuser->user)) {
   header('Location: /?logintype=logout&session=expired');
   die();
}

#3

Updated by Grégory Duchesnes over 8 years ago

Hi Markus and thanks for your answer.

The SQL_NO_CACHE line comes from a hook in logoff_pre_processing. I use it to make sure that sessionData is cleared on logout (might be useless in 6.1 but 4.5 used to leave some crap behind). Here follows the code, as you can see, since the user session has not been found by TYPO3 (ses_id=0) it can not do any harm.

class Tx_Espacesante_Hooks_T3libUserauth {
    public function logoff_pre_processing($params, $obj) {
        if($obj->user_table != 'be_users') {
            $res = $GLOBALS['TYPO3_DB']->exec_SELECTquery(
                '/*! SQL_NO_CACHE */ ses_userid',
                'fe_sessions',
                'ses_id='.intval($obj->id)
            );

            if($GLOBALS['TYPO3_DB']->sql_num_rows($res)) {
                $row = $GLOBALS['TYPO3_DB']->sql_fetch_assoc($res);
            }

            if ($row) {
                $GLOBALS['TYPO3_DB']->exec_DELETEquery(
                    'fe_sessions',
                    'ses_id='.intval($obj->id)
                );

                $GLOBALS['TYPO3_DB']->exec_UPDATEquery(
                    'fe_users',
                    'uid=' . $row['ses_userid'],
                    array('uc' => '')
                );
            }
            if(method_exists($GLOBALS['TSFE']->fe_user, removeSessionData)) $GLOBALS['TSFE']->fe_user->removeSessionData();
        }
    }
}

Thanks for the tip about EidUtility, i'm aware of this class but i need a proper $GLOBALS['TSFE'] for further treatment.

#4

Updated by Markus Klein over 8 years ago

Regarding the Eid. Just use the getTSFE() function and assign it to the global variable. It is much better to use API here, since if we need to change stuff somehow in the creation process of TSFE, you ext does not break. ;-)

$GLOBAL['TSFE'] = \TYPO3\CMS\Frontend\Utility\EidUtility::getTSFE();
feuser = \TYPO3\CMS\Frontend\Utility\EidUtility::initFeUser();
if (empty($feuser->user)) {
   header('Location: /?logintype=logout&session=expired');
   die();
}

I'm not sure if the problem is then database related. You've to check the code for initalizing the fe_user why no user data is fetched.
Can you maybe also check if $feuser is an object at all?

#5

Updated by Grégory Duchesnes over 8 years ago

I made some new tests and using APC as a cache backend, therefore lowering the load on the database, significally reduced the problem.
Furhtermore i did not have rootpageid set in my realurl config which triggered some more useless queries, i fixed that.

I still have a few disconnects but their number has been reduced by a factor of 5 or so.

that's weird...

#6

Updated by Grégory Duchesnes over 8 years ago

Looking at my stats it is now clear that the remaining disconnections are due to internet explorer 11.
I'll try to set [FE][lockHashKeyWords] = '' to see if it is related to the fact that the useragent changes during connection (a bug that used to occur with IE8)

I've seen bug #53818 but it concerns only BE and is Ext.Direct related (which i don't use).

For the records i already have a P3P policy and my Servername does not contain any "_" character

#7

Updated by Mathias Schreiber over 7 years ago

  • Status changed from New to Needs Feedback
  • Assignee set to Mathias Schreiber

Hi Grégory,

any news here?

#8

Updated by Grégory Duchesnes over 7 years ago

Hi Mathias,

I forgot to send a feedback, i'm really sorry.

I couldn't find a definitive solution to my problem but i managed to reduce its impact thanks to a deep analysis of the application.

To make it short i managed to reduce it by a factor of 4 by activating APC cache, which proves that part of the problem was database related.

Then i found that most of the remaining lost connections were on Internet Explorer 11 and i found the explaination on this feedback : https://connect.microsoft.com/IE/feedback/details/810700/subject-ie11-is-losing-cookie-information-and-thus-becoming-detached-from-a-web-application-session

For this second problem, i had no other choice than displaying a specific message for IE11 users when they got disconnected.

Hope this helps

#9

Updated by Alexander Opitz about 7 years ago

So we can close this issue or is something todo for us?

#10

Updated by Wouter Wolters almost 7 years ago

  • Status changed from Needs Feedback to Closed

Closed as solved.

Also available in: Atom PDF