• 0 Vote(s) - 0 Average
  • 1
  • 2
  • 3
  • 4
  • 5
Session: Error while trying to free lock for ci_session

#1
I've recently upgraded to 3.0 in production. I receive a hundred or so of these errors in the logs each day (I have around 20,000 actively logged in users at any given time. A few pages have a light sprinkling of user-initiated AJAX):

Session: Error while trying to free lock for ci_session
Session: Unable to obtain lock for ci_session

My config.php:
PHP Code:
$config['sess_driver'] = 'redis';
$config['sess_cookie_name'] = 'ci_session';
$config['sess_expiration'] = 604800// 1 week
$config['sess_save_path'] = 'tcp://remote_redis_ip:6379';
$config['sess_match_ip'] = FALSE;
$config['sess_time_to_update'] = 1800;
$config['sess_regenerate_destroy'] = FALSE

To be clear, I prefer this to 2.x's non-locking implementation of sessions which was probably the cause of hours of grief when I was working on weird session issues that users were reporting. It seems from the documentation that calling session_write_close() within my application could potentially reduce these occurrences (I'm assuming it's because it's releasing the lock on the session earlier in the request).

My question is where is the best place for me to call it? I don't modify the session anywhere in the application after the user is logged in so I figure to call it in each controller's constructor like so:

PHP Code:
function __construct() {
 
   parent::__construct();
 
   session_write_close();


Am I on the right track here?
Reply

#2
Yes, you are on the right track.
However, these messages are a sign for slow page loads (>5 seconds, to be more precise), so you should probably look into that as well.
Reply

#3
That's funny - I arrived at this post after Googling my error and the top result is me asking about the same error two years ago. I recently had a spate of Redis "read error on connection" issues which I managed to resolve by throwing more Redis at it but that in turn just exacerbated the "Error while trying to free lock for ci_session" issue which I never fixed so I'm attempting it again.

As Narf suggested, it is probably slow page loads. My average app server response time is < 60ms while my average page load time hovers around 8s. However, the page load range varies significantly from a min of 13ms to a max of 31500ms which is not entirely unexpected since I run a user generated content site where around 80% of my users are now on mobile with a good number of them in developing areas with unreliable connections. So assuming the problem with the session errors do indeed lie with slow page loads, is it because the session lock is held until a page is fully rendered and is highly dependent on a user having a fast connection? Or should I actually be looking for a section of my site somewhere that really is taking >5 seconds to process that my monitors and profilers may be missing?

Environment (updated since I first started this thread):
CI 3.1.3
Nginx 1.11.10
PHP 7.0.15
Ubuntu 16.04
Sessions are now saved in a dedicated Redis cluster separate from regular cache
Twemproxy for distributed Redis sessions across multiple servers

Updated config since first thread post:
PHP Code:
$config['sess_save_path'] = '/home/user/site/nutcracker/session.sock'
Reply

#4
(03-04-2017, 12:47 AM)Nichiren Wrote: So assuming the problem with the session errors do indeed lie with slow page loads, is it because the session lock is held until a page is fully rendered and is highly dependent on a user having a fast connection? Or should I actually be looking for a section of my site somewhere that really is taking >5 seconds to process that my monitors and profilers may be missing?

Both ... but more of the latter.

"Render" is the wrong term to use (that happens client side). However, by default, the lock is released after the entire script execution completes, which includes completely flushing the output, and that does depend on connection speeds.
You can get work around that by calling session_write_close() as soon as you no longer need to access session data.

But that being said, even mobile connections are quite speedy nowadays, so most of the time it is inefficient server-side processing that's causing problems.
Reply

#5
(03-06-2017, 04:14 AM)Narf Wrote: Both ... but more of the latter.

"Render" is the wrong term to use (that happens client side). However, by default, the lock is released after the entire script execution completes, which includes completely flushing the output, and that does depend on connection speeds.
You can get work around that by calling session_write_close() as soon as you no longer need to access session data.

But that being said, even mobile connections are quite speedy nowadays, so most of the time it is inefficient server-side processing that's causing problems.

Thanks, Narf. That at least gives me a definitive place to start. I've placed this at the bottom of index.php:
PHP Code:
// Log slow script execution times
$scriptExeTime microtime(true) - $_SERVER["REQUEST_TIME_FLOAT"];
if (
$scriptExeTime 5.0) {
 
log_message('ERROR'"{$scriptExeTime} " current_url());


Unfortunately, I'm still getting the "Error while trying to free lock" error but without this log message to accompany it. Is the bottom of index.php the best place to put this log or is there a better way to do this? I've also added current_url() and stack trace when logging the "free lock" error but the urls aren't consistent (it can be anywhere). I have both NewRelic and Blackfire to help me profile the application but I can't seem to catch the specific issue through them either.

In regards to session_write_close(), I forgot to mention that I've had a MY_Session.php override with this constructor:

PHP Code:
public function __construct(array $params = array())
{
 
   $CI =& get_instance();
 
   $ciController $CI->uri->segment(10);
 
   $ciFunction $CI->uri->segment(20);

 
   $driver config_item('sess_driver');
 
   if ($driver === 'redis') {
 
       $CI =& get_instance();
 
       $this->_setup_redis($CI);
 
       if ( ! $this->isConnected) {
 
           return NULL;
 
       }

 
       // Don't call session start if a user is not logged in unless
 
       // they are in the login or registration sections.
 
       if ($ciController === 'login' && $ciFunction === 'check') {
 
           // Ignore login check
 
       } elseif ($ciController === 'register') {
 
           // Ignore registration
 
       } else {
 
           $cookieName $CI->config->item('sess_cookie_name');
 
           if (empty($_COOKIE[$cookieName])) {
 
               // Not logged in since no session cookie
 
               return NULL;
 
           }

 
           $session $this->redis->get("ci_session:{$_COOKIE[$cookieName]}");
 
           if (empty($session) || strpos($session'username') === FALSE) {
 
               // Session ID found in cookie but no active session found
 
               // so skip trying to start a session.
 
               return NULL;
 
           }
 
       }
 
   }
 
   parent::__construct($params);

 
   // Release session locks early to reduce locking errors
 
   // but not for sections that set session data.
 
   if ($ciController !== 'login' &&
 
       $ciController !== 'register' &&
 
       $ciController !== 'account') {
 
       session_write_close();
 
   }


The top part prevents session_start() from being called when a user isn't logged in and the bottom (should) always calls session_write_close() right after session_start() is called in the parent constructor. Is this the most efficient place to call session_write_close()? I've also always been uncomfortable modifying core functions so are there any glaring issues with the above code as well?
Reply

#6
I'm convinced there's something more at play here. Our app makes heavy use of AJAX and I had to stop logging this message as it fills up our error log. Adding session_write_close helps but does not fix the issue completely. It's not an issue with long running requests I've seen this happen on a request that completed in <100ms.

Relevant thread: https://forum.codeigniter.com/thread-652...=free+lock
Issue on Redis's Github: https://github.com/phpredis/phpredis/issues/816

What version of phpredis are you using? I'm testing a new build of our app on PHP7 and phpredis 3.1.1 and forgot about this issue. I'll do some tests to see if the newer versions of phpredis fix it I was running PHP 5.x and phpredis 2.2.8 while those threads were current.

[edit]
After some quick initial tests I haven't been able to reproduce this error using CI 3.1.3, PHP 7.0 and phpredis 3.1.1. I'll keep an eye on the log and reply if I see it happen again.
[/edit]
Reply

#7
Thanks for the tip on phpredis. I'm on 2.2.7 which is the default package on Ubuntu 16.04. I tried 3.1.1 but I couldn't get it to work with Twemproxy for some reason. Please update the thread if upgrading to phpredis 3.1.1 indeed fixes your issue!

Otherwise, I also don't have requests that go past 5 seconds based on the script execution time log I noted above (maybe one or two a week which wouldn't account for the hundreds of lock errors I'm getting). I was getting these errors before I implemented more AJAX on the site but it's definitely showing up more now as my new AJAX widget gets called more often (I log the url requested along with the lock errors).

Have you explored bypassing the session altogether for AJAX requests that require some verification but aren't too sensitive in nature by using JWT (Json Web Tokens) in browser session storage? Or at the least, my widget only runs for logged in users and is specific to a user so perhaps even just appending a csrf token to the request could mitigate someone casually trying to view someone else's widget (again, information isn't very sensitive). I'm just hesitant doing either before getting someone else's thoughts on this.
Reply

#8
The build I'm testing with is our companies product based on my addon Cinder for CI3. The repo in that link is horribly out of date and the latest version will be moving from my personal Github to my companies Github and released under the MIT license in the next few months. It turns CI apps into single page apps and makes use of client side templating, caching in local storage, uploads through file reader, abortable and queueable AJAX requests through a conduit wrapper. The main portion of our app consistently has 4-6 AJAX requests running across multiple subdomains.

Our application requires roles, permissions, and is locked behind a login so sessions make sense in our case. I'm not entirely sold on JWT but perhaps the right use case hasn't come along yet.

Adding session_write_close is still a good idea as it helps performance. It sounds like this issue was a bug in phpredis and not CI *fingers crossed*
Reply

#9
(03-13-2017, 06:23 PM)spjonez Wrote: The build I'm testing with is our companies product based on my addon Cinder for CI3. The repo in that link is horribly out of date and the latest version will be moving from my personal Github to my companies Github and released under the MIT license in the next few months. It turns CI apps into single page apps and makes use of client side templating, caching in local storage, uploads through file reader, abortable and queueable AJAX requests through a conduit wrapper. The main portion of our app consistently has 4-6 AJAX requests running across multiple subdomains.

Our application requires roles, permissions, and is locked behind a login so sessions make sense in our case. I'm not entirely sold on JWT but perhaps the right use case hasn't come along yet.

Adding session_write_close is still a good idea as it helps performance. It sounds like this issue was a bug in phpredis and not CI *fingers crossed*

Did upgrading to the latest phpredis build ultimately resolve your session lock issue for you? I've finally gotten my workload under control to have the time to test this hypothesis out but I figured I'd ask how you fared before I jump into it.
Reply

#10
(03-18-2017, 08:51 PM)Nichiren Wrote: Did upgrading to the latest phpredis build ultimately resolve your session lock issue for you? I've finally gotten my workload under control to have the time to test this hypothesis out but I figured I'd ask how you fared before I jump into it.

Our staging area doesn't have the same traffic as our current production box so I can't say 100% yet, but I can say it hasn't happened once so far. Given how often it occurred before and that the steps I used to reproduce it before no longer cause the error I'm leaning towards it being solved.
Reply


Digg   Delicious   Reddit   Facebook   Twitter   StumbleUpon  


Users browsing this thread:
1 Guest(s)


  Theme © 2014 iAndrew  
Powered By MyBB, © 2002-2017 MyBB Group.