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

#31
That's correct, that's what sticky sessions do they send all requests back to the same box. No it's not ideal but it's better than 5s page loads. You could try Redis and see if that helps. If it doesn't I'd wager the performance bottleneck is an issue with your application code and not CI. I've never tried Memcache but nothing inside our application takes 5s to load.

If you use LB managed sticky sessions use the files driver as you would for a single instance. You should never have to change php.ini settings for anything related to sessions while using CI AFAIK.

The downside to this if you deploy a new application bundle that requires an instance restart or if they are killed by managed updates every user who's using sessions on that box will be logged off.

You could also try the database session library.

You should create a separate thread for this though, this thread is about session locks not performance issues.
Reply

#32
Well yes.
But for now I have to believe that everything will work Smile
I do not believe that this is on my side problem.
As I mentioned:
Quote:When user logs in app I store his data in session. Because I do not want to call API to fetch user data on every single request specially because users do not change their information very often. Just as example, when user changes the data, call API (before call I need to check is user logged in or not), wait for api, if there is no error in API response update the Session.

How this can be problem on my side?
API response time is 100 - 120ms so my code is just fine.

After update to 3.x CI form 2.x I am experiencing this problem Sad
Maybe the problem is with Memcached, who knows.. I will try with Redis to.
Reply

#33
(05-25-2016, 01:32 PM)spjonez Wrote:
Narf Wrote:Well, I don't have another response.
If I did, we'd have the whole thing figured out by now.

Is there anything else I can provide that would be useful to you as a core developer or are we on our own?

Best thing I could look at is the call details (method names & params, similar to a stack trace) for all CI_Session_redis_driver methods, in the order that they appear, for the request that triggers the issue (and ideally for the one preceeding it too). I'm afraid this is hard to obtain without monkey-patching the class to log that info.

I could also look at your code, the pieces that do session-related stuff anyway, but I highly doubt seeing anything related to this particular issue - that's a waste of time.

But in any case, that would (hopefully) give me just enough to make an educated guess ... I sense that you're relying too much on my directions, for something that you are more well-equipped for in this instance - I can't reproduce the issue, I don't even have Redis or Memcached, I can do literally nothing but guess. It's not that you're completely on your own, but rather you don't really need my help as much as you think you do.
Reply

#34
(05-25-2016, 02:53 PM)Narf Wrote: Best thing I could look at is the call details (method names & params, similar to a stack trace) for all CI_Session_redis_driver methods, in the order that they appear, for the request that triggers the issue (and ideally for the one preceeding it too). I'm afraid this is hard to obtain without monkey-patching the class to log that info.

I could also look at your code, the pieces that do session-related stuff anyway, but I highly doubt seeing anything related to this particular issue - that's a waste of time.

But in any case, that would (hopefully) give me just enough to make an educated guess ... I sense that you're relying too much on my directions, for something that you are more well-equipped for in this instance - I can't reproduce the issue, I don't even have Redis or Memcached, I can do literally nothing but guess. It's not that you're completely on your own, but rather you don't really need my help as much as you think you do.

Thanks, I've added a ton of logging to the Redis library to see if I can make sense of what's happening. Annoyingly it's hard to replicate and I haven't found a specific set of steps to reproduce the error reliably. When I can narrow it down I'll post any info I find.

What Redis extension did you develop with? phpredis?
Reply

#35
(05-25-2016, 03:58 PM)spjonez Wrote: What Redis extension did you develop with? phpredis?

s/with/for/

Believe it or not, I've only ever looked at the manual and have never run redis.
But yes, phpredis is what it requires.
Reply

#36
I finally managed to solve the issue by switching to redis driver!
The code is same just the driver is different!

So, conclusion is this: somewhere in memcached driver is bug with locking mechanism.
Thanks @spjonez, @narf it would be nice if you guys can fix this in next release...
Reply

#37
Did that solve your performance issue or the lock error?
Reply

#38
(05-26-2016, 12:46 AM)Narf Wrote: Believe it or not, I've only ever looked at the manual and have never run redis.
But yes, phpredis is what it requires.

I'm seeing some really odd results in my logs, does this make any sense to you?

Code:
    public function write($session_id, $session_data)
    {
        if ( ! isset($this->_redis))
        {
            return $this->_fail();
        }
        // Was the ID regenerated?
        elseif ($session_id !== $this->_session_id)
        {
            if ( ! $this->_release_lock('1') OR ! $this->_get_lock($session_id))
            {
                return $this->_fail();
            }

            $this->_key_exists = FALSE;
            $this->_session_id = $session_id;
        }

        if (isset($this->_lock_key))
        {
            $this->_redis->setTimeout($this->_lock_key, 300);
            if ($this->_fingerprint !== ($fingerprint = md5($session_data)) OR $this->_key_exists === FALSE)
            {
                if ($this->_redis->set($this->_key_prefix.$session_id, $session_data, $this->_config['expiration']))
                {
                    $this->_fingerprint = $fingerprint;
                    $this->_key_exists = TRUE;
                    return $this->_success;
                }

                return $this->_fail();
            }

            return ($this->_redis->setTimeout($this->_key_prefix.$session_id, $this->_config['expiration']))
                ? $this->_success
                : $this->_fail();
        }

        return $this->_fail();
    }

Only change is to add '1' to _release_lock.

Code:
    public function close()
    {
        if (isset($this->_redis))
        {
            try {
                if ($this->_redis->ping() === '+PONG')
                {
                    $this->_release_lock('2');
                    if ($this->_redis->close() === $this->_failure)
                    {
                        return $this->_fail();
                    }
                }
            }
            catch (RedisException $e)
            {
                log_message('error', 'Session: Got RedisException on close(): '.$e->getMessage());
            }

            $this->_redis = NULL;
            return $this->_success;
        }

        return $this->_success;
    }

Only change is to add '2' to _release_lock.

Code:
    protected function _release_lock($code = 0)
    {
        if (isset($this->_redis, $this->_lock_key) && $this->_lock)
        {
            $exists = $this->_redis->exists($this->_lock_key);
            $del = $this->_redis->delete($this->_lock_key);

            if ( !$del)
            {
                $exists2 = $this->_redis->exists($this->_lock_key);

                log_message('error', 'Session: Error while trying to free lock for '.$this->_lock_key . ', code=' . $code . ', del=' . var_export($del,true) . ', exists=' . var_export($exists,true) . ', exists2=' . var_export($exists2,true));
                return FALSE;
            }

            $this->_lock_key = NULL;
            $this->_lock = FALSE;
        }

        return TRUE;
    }

Added exists calls before and after the delete and to print to the delete call's response and $code being passed. This is the message it produces:

Session: Error while trying to free lock for ci_session:7ed553ebbca1ba962394dcc3a0c934e85b1c25c3:lock, code=2, del=0, exists=true, exists2=false

The key exists before the delete call, the delete call returns 0, yet the key is in fact deleted as shown by the second exists call? The only way I've been able to reproduce this semi reliably is to trigger 2 or more concurrent AJAX requests.

According to the Redis documentation delete should return a long if successful or 0 if it fails. Is this also true for keys set to expire? I've never used those before to know what the expected behaviour is in this situation.
Reply

#39
We already knew that the close() call is triggering it, that was shown in the stack_trace.txt you attached yesterday(?).

(05-26-2016, 11:13 AM)spjonez Wrote:
Code:
    protected function _release_lock($code = 0)
    {
        if (isset($this->_redis, $this->_lock_key) && $this->_lock)
        {
            $exists = $this->_redis->exists($this->_lock_key);
            $del = $this->_redis->delete($this->_lock_key);

            if ( !$del)
            {
                $exists2 = $this->_redis->exists($this->_lock_key);

                log_message('error', 'Session: Error while trying to free lock for '.$this->_lock_key . ', code=' . $code . ', del=' . var_export($del,true) . ', exists=' . var_export($exists,true) . ', exists2=' . var_export($exists2,true));
                return FALSE;
            }

            $this->_lock_key = NULL;
            $this->_lock = FALSE;
        }

        return TRUE;
    }

Added exists calls before and after the delete and to print to the delete call's response and $code being passed. This is the message it produces:

Session: Error while trying to free lock for ci_session:7ed553ebbca1ba962394dcc3a0c934e85b1c25c3:lock, code=2, del=0, exists=true, exists2=false

The key exists before the delete call, the delete call returns 0, yet the key is in fact deleted as shown by the second exists call? The only way I've been able to reproduce this semi reliably is to trigger 2 or more concurrent AJAX requests.

According to the Redis documentation delete should return a long if successful or 0 if it fails. Is this also true for keys set to expire? I've never used those before to know what the expected behaviour is in this situation.

Are you reading the same documentation? Nitpicky and possibly irrelevant, but the one I'm reading here says nothing about failures - 0 is rather an "I deleted 0 keys" count. Smile
I may be trying to read between the lines while there's nothing there to read, but if you're not reading the same docs, you may also not be using the same extension ...

Other than that, it is bizzare that delete() would return 0 while still deleting a key, and I see no logic in returning 0 for keys with expiry time, but ... you'd have to verify that. As I said previously - I don't have a Redis instance to test with.

There is the chance of a phpredis bug, especially if you're not using the same extension, or not the latest version.

Either way, that doesn't explain how the exact same issue would be triggered with Memcached too. Unless phpredis has copied code straigh from the memcached extension, that's almost an unimaginable coincidence.
Reply

#40
(05-26-2016, 11:51 AM)Narf Wrote: Are you reading the same documentation? Nitpicky and possibly irrelevant, but the one I'm reading here says nothing about failures - 0 is rather an "I deleted 0 keys" count. Smile
I may be trying to read between the lines while there's nothing there to read, but if you're not reading the same docs, you may also not be using the same extension ...

Other than that, it is bizzare that delete() would return 0 while still deleting a key, and I see no logic in returning 0 for keys with expiry time, but ... you'd have to verify that. As I said previously - I don't have a Redis instance to test with.

There is the chance of a phpredis bug, especially if you're not using the same extension, or not the latest version.

Either way, that doesn't explain how the exact same issue would be triggered with Memcached too. Unless phpredis has copied code straigh from the memcached extension, that's almost an unimaginable coincidence.

I'm using phpredis 2.2.7 the latest release available: https://github.com/phpredis/phpredis/releases

Documentation I'm reading: https://github.com/phpredis/phpredis#del-delete

Exists shows the key exists, delete returns 0, exists then shows it does not. I'm not sure what to make of that unless it's expiring between the two calls which seems unlikely.

I'm not using Memcache nor have I tried it at any point so I can't comment on issues with that library.

This makes the error disappear but is probably not the way to solve it:

Code:
    protected function _release_lock()
    {
        if (isset($this->_redis, $this->_lock_key) && $this->_lock)
        {
            if ( ! $this->_redis->delete($this->_lock_key) && $this->_redis->exists($this->_lock_key))
            {
                log_message('error', 'Session: Error while trying to free lock for '.$this->_lock_key);
                return FALSE;
            }

            $this->_lock_key = NULL;
            $this->_lock = FALSE;
        }

        return TRUE;
    }

I posted this as an issue on phpredis's Github page to see if I can get clarification on deleting keys set to expire: https://github.com/phpredis/phpredis/issues/816
Reply


Digg   Delicious   Reddit   Facebook   Twitter   StumbleUpon  


Users browsing this thread:
1 Guest(s)


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