Session drops

[hzorr]

Hi We are having some abnormal session losses when having some concurrent ajax calls (even if rotation is switched off) using session file engine on (CentOS 6.6, php 5.3.3, Apache/2.2.15).

The problem, seems, is in flock() function which is used in engine. Just for testing we have changed the code to lock and unlock session file with following function calls:

 protected function lockFile($filepath){
        clearstatcache();
        $lockname=$filepath.".lock";
        // if the lock already exists, get its age:
        $life=@filectime($lockname);
        // attempt to lock, this is the really important atomic action:
        while (!@mkdir($lockname)){
            if ($life)
                if ((time()-$life)>120){
                    //release old locks
                    rmdir($lockname);
                    $life=false;
                }
            usleep(rand(50000,200000));//wait random time before trying again
        }
    }

    protected function unlockFile($filepath){
        $unlockname= $filepath.".lock";
        return @rmdir($unlockname);
    }

And it seems the session doesn't drop anymore, Any thoughts on this? Thanks

[WanWizard]

I don't really see how the current process of open, lock, truncate, write, unlock, close would cause processes to lose a session, reading it would use a shared lock, and it would wait for an exclusive lock to be released before reading it.

Fuel's sessions are not atomic, so if you have concurrent requests that update the session, they will overwrite each others session data. This is different from PHP's native session behavior, which locks the session file on session_start() and releases the lock on session_end(), which also means you can forget concurrent access all together.

Can you explain what exactly your problem is (= define "loss of session"), and why you believe your suggestion solves that problem?

[hzorr]

Hi, thanks for reply.

"loss of session" in my case mean that some of ajax calls return new sessionID and empty session data . We suppose, it is the flock() function which is advisory on some Linux platforms not properly locking the session file and maybe the second thread is getting the truncated data. We just for testing replaced the flock() function exclusive locking with above written function calls, and it works. But in this case reading cant use a shared lock.

[kenjis]

I'm not sure, but we don't call fflush() before unlocking. https://github.com/fuel/core/blob/1.8/develop/classes/session/file.php#L267-280

What if you add fflush()?

fflush($handle);
flock($handle, LOCK_UN);

[hzorr]

Yes, we have tried using fflush(), it is not helping. I can describe the situation in our project when its happening, may be it will help to reproduce it. Imagine a page with list of persons on left and when you click on one of them, on right side opens the form, with ajax call, with a lot of controls like comboboxes etc.. and each of them getting their data with ajax calls from server. So when you working with list and rapidly click through persons after some time one of the ajax requests returns the new sessionID in cookies.

[it-can]

I sometimes experience the same issue, it seems that ajax calls have something to do with this..

[WanWizard]

file based sessions too, or using a different backend?

[it-can]

Yup file based... Redis no problems so far...

[WanWizard]

@hzorr @it-can when you experience loss of session, do you have a debug entry in the log explaining why you got a new session? The Session driver writes debug entries when it detects an issue, to debug problems like this.

[it-can]

Also see this: http://fuelphp.com/forums/discussion/13628/ajax-session-rotation

He uses DB session btw...

[WanWizard]

No more feedback on this? Other than a suggestion, I haven't seen what may cause this. flock is mentioned, but which flock? In read, or in write?

Read uses LOCK_SH, a reader lock, so it should not be a problem having simultaneous session read operations. Write uses LOCK_EX, which is blocking for all other operations. Both read and write loop endlessly waiting for a lock.

The only way a request starts with a new session, is if

• the session file no longer exist (most logical reason would be a session id rotation)
• the fopen() call on the file already fails
• the session file is zero bytes

What path in the code is exactly taken is easy enough to find by adding some logger() statements in every path. Since I don't have the problem here and can't reproduce it, can someone do this, and determine why exactly you are sometimes not able to read an existing session file on ajax calls?

[hzorr]

Hi, Can you send new file.php file with added logging functions you need. We will replace it in our server try to reproduce session drops and send you back log file.

[WanWizard]

Here you do. It adds log entries at debug level, so your logging should be set to L_ALL.

file.php.txt

(rename the file to file.php, can't attach a php file here)

[hzorr]

Here it is 12.txt

[WanWizard]

I don't see a single read operation in that log, only writes? And there are all to the same file, so no new-session issues?

p.s. there are a lot of fatal errors in there too...

[WanWizard]

I am currently running this test in 5 concurrent requests which will mimic a session cycle:

    public function action_test($instance)
    {
        for ($i = 1; $i < 101; $i++)
        {
            $file = '/tmp/lockfile';
            touch($file);

            logger('debug', 'LOCK TEST ('.$instance.'): SHARED - Requesting lock at '.time().'.');
            $handle = fopen($file, 'r');
            if ($handle)
            {
                // wait for a lock
                while( ! flock($handle, LOCK_SH | LOCK_NB))
                {
                    logger('debug', 'LOCK TEST ('.$instance.'): SHARED - Waiting for a lock at '.time().'.');
                    sleep(1);
                }

                logger('debug', 'LOCK TEST ('.$instance.'): SHARED - Got a lock at '.time().'.');

                sleep (rand(1,3));

                //release the lock
                flock($handle, LOCK_UN);

                logger('debug', 'LOCK TEST ('.$instance.'): SHARED - Released lock at '.time().'.');

                // close the file
                fclose($handle);
            }

            sleep (rand(1,5));

            logger('debug', 'LOCK TEST ('.$instance.'): EXCLUSIVE - Requesting lock at '.time().'.');
            $handle = fopen($file, 'r');
            if ($handle)
            {
                // wait for a lock
                while( ! flock($handle, LOCK_EX | LOCK_NB))
                {
                    logger('debug', 'LOCK TEST ('.$instance.'): EXCLUSIVE - Waiting for a lock at '.time().'.');
                    sleep(1);
                }

                logger('debug', 'LOCK TEST ('.$instance.'): EXCLUSIVE - Got a lock at '.time().'.');

                sleep (rand(1,3));

                //release the lock
                flock($handle, LOCK_UN);

                logger('debug', 'LOCK TEST ('.$instance.'): EXCLUSIVE - Released lock at '.time().'.');

                // close the file
                fclose($handle);
            }

            sleep (rand(1,5));
        }

        echo 'finished';
    }

When finished I'll import the log into a tool for swimlane request analysis, to see if there are concurrency issues logged.

[hzorr]

Sessionlog.php.txt Here is file without any fatal errors Session: Session file "/data/www/fuel_sessions/fuelfid_837d5d36e8262e82c51fa7029959a6ea" is empty These are read operation logs I think, when the session is beeing dropped, you have no reading log for non error case.

[WanWizard]

When a session is dropped, you should see a new session id appear in the filename, and I don't see that in your logs. Also, your log doesn't show any read errors, which would cause a new session to be created.

[WanWizard]

In the meantime, my tests have run and I've analyzed the results.

I had 5 concurrent requests running, each attempting a read lock followed after a random delay by a write look, in a loop of 100 times. This resulted in 6276 debug log entries. This ran for just over 28 minutes.

At no time there was a read operation active while there was a write lock. There were plenty of concurrent read locks, as expected. I did not find any concurrency issues with the locking mechanism as it is currently used in the file driver.

[WanWizard]

@hzorr

Here's a modified driver that does a lot more logging. file.php.txt

[hzorr]

Here is log file, lost session somewhere in the end 13.php.txt

[WanWizard]

Very intresting, thank you. I have a feeling this is a race condition, where the waiting reads are being released after a write unlock, but before the file close. If PHP buffers output, the file is still empty at that point.

Could you replace

flock($handle, LOCK_UN);

by

fflush($handle);
flock($handle, LOCK_UN);

in _write_file() and see if that fixes the problem?

[hzorr]

We have tried that solution before. It doesn't help. Here's log file with fflush added. 12(1).php.txt

[hzorr]

Maybe the problem is that the read acquiring the file handle before write releases lock?

[WanWizard]

No, according to the log the write lock is released before the read attempts to read the file. But it still finds a file with size zero.

It could also be that PHP caches complete file stats when it first access the file. Which means that fhe file_exists() call in read would see the file, which has size 0 at that moment because write is busy, and later when it checks the file size, the 0 that is in cache is returned instead of the actual filesize.

You can test that theory by adding

clearstatcache();

in _read_file(), just above the filesize() check.

[hzorr]

You are right!!! I have added second filesize() check after clearstatcache() and logged size values. in some cases it showed that size is 0 after clearstatcache() it changes to some bites.

[WanWizard]

So you can confirm that clearing the stat cache in read solves the problem?

[hzorr]

Yes, but with fflush($handle) in write, I'm not sure if its works without it

[it-can]

sounds promising!

[WanWizard]

@hzorr can you test if the flush is really required? Don't want to put any code in there that isn't needed.

[WanWizard]

It's probably even better to remove the file size check, and simply use file_get_contents() to retrieve the session data.

[WanWizard]

This should do it, let me know if this works for you guys

[it-can]

thanks!