Random "Unable to acquire a lock for caching" exception on Moodle 4.1

Random "Unable to acquire a lock for caching" exception on Moodle 4.1

by Susana L. -
Number of replies: 20
Picture of Particularly helpful Moodlers

Hi,

We are experiencing an issue this year with moodle 4.1. that never happened before and we still can't understand if this is some system configuration problem or if it is a Moodle 4 related issue. We have several reports from our academic community of the exception "Unable to acquire a lock for caching" (ex_unabletolock). The exception shows up randomly when using moodle and we are not able to deliberately reproduce.

We have the same cache configuration as on previous Moodle instances, the same Moodle architecture (2 App servers + DB Server - PostgreSQL), and approximately the same usage (40k users, 6k courses, 30k-40k logins/day).
We have a fresh new Moodle 4.1 for the new academic year and the issue only occurs on this instance.

We tried to clean caches, restart memcached, reconfigure user permissions... and we are running out of ideas.  

I would like to know if someone is having a similar issue. Any feedback would be greatly appreciated.

Thank you,
susana

Average of ratings: -
In reply to Susana L.

Re: Random "Unable to acquire a lock for caching" exception on Moodle 4.1

by Howard Miller -
Picture of Core developers Picture of Documentation writers Picture of Particularly helpful Moodlers Picture of Peer reviewers Picture of Plugin developers
It's not really an answer but you might want to consider switching from memcached to Redis.

We had a lot of weird issues with memcached that went away with redis. Granted, Redis introduced a couple of new ones...
Average of ratings: Useful (1)
In reply to Susana L.

Re: Random "Unable to acquire a lock for caching" exception on Moodle 4.1

by Susan Mangan -
Picture of Particularly helpful Moodlers
We just upgraded to 4.1 and are seeing the same behavior. Our sysadmin deleted the /moodledata/muc/config.php file so it would re-generate - and this resolved our issues (for now).
Average of ratings: Useful (3)
In reply to Susan Mangan

Re: Random "Unable to acquire a lock for caching" exception on Moodle 4.1

by Howard Miller -
Picture of Core developers Picture of Documentation writers Picture of Particularly helpful Moodlers Picture of Peer reviewers Picture of Plugin developers
Bear in mind that just sets all the cache settings back to default - so you're now caching to the file store (usually a bad thing for performance).
Average of ratings: Useful (3)
In reply to Howard Miller

Re: Random "Unable to acquire a lock for caching" exception on Moodle 4.1

by Susana L. -
Picture of Particularly helpful Moodlers
We cleaned moodledata/muc but as Howard warned we cant keep the defaults because of performance. We will configure memcached only for some modules, and we will see how it works. I will keep this thread updated. Thank you!
In reply to Susana L.

Re: Random "Unable to acquire a lock for caching" exception on Moodle 4.1

by Susan Mangan -
Picture of Particularly helpful Moodlers
Hi Susana,

We continue to see the ex_unabletolock error regularly in the php error logs - so assuming these are being triggered by cron. We haven't had a report of it affecting any of our end users until today. I cleared all the caches including the memcache store and the user was able to access the system again.

Interested on hearing an update from you on your experiences and findings? Seems like the issue is linked to memcache and upgrading to 4.1 somehow.

Edit: or it could just be happening to admins with "Susan" in their name 😆
Average of ratings: Useful (1)
In reply to Susan Mangan

Re: Random "Unable to acquire a lock for caching" exception on Moodle 4.1

by Susana L. -
Picture of Particularly helpful Moodlers
Hi Susan, I was almost sure the issue was related to your last hypothesis "admins with Susan in their name" but today we have Alain also reporting it 😃

We also keep seeing an ex_unabletolock error in our logs but I don't think that one is the same that is showed to users. As you said, that one is triggered by cron. 
We hope that the upgrade to 4.1.6 resolves the issue... maybe it was related to https://tracker.moodle.org/browse/MDL-79349
Average of ratings: Useful (1)
In reply to Susana L.

Re: Random "Unable to acquire a lock for caching" exception on Moodle 4.1

by Alain Raap -
We are using Redis in a Moodle 4.1 environment and have the same problem (error ex_unabletolock) with tasks that
take a long responsetime. Is it a session or muc problem that this problem occurs? I can't see the error in our logfiles,
and I'm not able to debug in our environment.

In our config file we use these settings for Redis:

$CFG->session_redis_acquire_lock_timeout = 120;
$CFG->session_redis_lock_expire = 7200;
In reply to Alain Raap

Re: Random "Unable to acquire a lock for caching" exception on Moodle 4.1

by Susana L. -
Picture of Particularly helpful Moodlers
We also didn't see the error in our logfiles.
We haven't had any reports since we upgraded to 4.1.6, but it's only been a week...
In reply to Susana L.

Re: Random "Unable to acquire a lock for caching" exception on Moodle 4.1

by Alain Raap -
We hoped that Moodle 4.1.6 would be the solution to our problems, but it still goes wrong.

There are several trackers about locking problems that aren’t resolved yet I saw on the Moodle Tracker site, on course level, but also in other parts of Moodle code.

In reply to Alain Raap

Re: Random "Unable to acquire a lock for caching" exception on Moodle 4.1

by Susan Mangan -
Picture of Particularly helpful Moodlers
Oh interesting. We haven't seen the issue come back since we made the move from memcached to redis. No end user reports and no php error log entries.

We are still on 4.1.5 but applied these 2 bug fixes manually:
https://tracker.moodle.org/browse/MDL-71909
https://tracker.moodle.org/browse/MDL-79017
In reply to Susan Mangan

Re: Random "Unable to acquire a lock for caching" exception on Moodle 4.1

by Alain Raap -
Both bugs work on our Moodle site in 4.1.6, the semi-colon problem in filenames wasn’t fun for teachers making courses sad
I’ll have a look for the open trackers about locking problems next week
In reply to Susan Mangan

Re: Random "Unable to acquire a lock for caching" exception on Moodle 4.1

by Alain Raap -
Here are the trackers I found that are still open and are about locking issues:

https://tracker.moodle.org/browse/MDL-77851
https://tracker.moodle.org/browse/MDL-77852

Is the CFG->session_redis_acquire_lock_timeout = 120 value too low or is there something else that's causing the
cache locking problems? I also see that there are a lot of session keys in Redis that aren't deleted and still are in
the database.
Average of ratings: Useful (1)
In reply to Susana L.

Re: Random "Unable to acquire a lock for caching" exception on Moodle 4.1

by Michael Schneider -
I do not have a solution. Just wanted to subscribe to the thread and let you know there is another admin experiencing these problems lets say since moodle 4.1.2(?) our first station after versions of 3.11. We also run memcached and have a custom muc config. We are now on 4.1.6 and the reason for the misbehaviour still remains unclear.
Average of ratings: Useful (1)
In reply to Michael Schneider

Re: Random "Unable to acquire a lock for caching" exception on Moodle 4.1

by Alain Raap -
Michael, we switched from memcached to Redis already some time ago as caching server.
Switching to Redis will not solve the problem as we have the same problem with caching locks.
I found out that it could be a performance issue, we tried the same functions on a server with
the same configuration and without user load, it wasn't a problem there to acquire a lock for
caching.

Anyone who has experience with Redis and io-threading? It's possible in the configuration file to 
configure extra io-threads. I haven't tested yet if this could make a difference.

This is the io-threads section in redis.conf configuration:

################################ THREADED I/O #################################

# Redis is mostly single threaded, however there are certain threaded
# operations such as UNLINK, slow I/O accesses and other things that are
# performed on side threads.
#
# Now it is also possible to handle Redis clients socket reads and writes
# in different I/O threads. Since especially writing is so slow, normally
# Redis users use pipelining in order to speed up the Redis performances per
# core, and spawn multiple instances in order to scale more. Using I/O
# threads it is possible to easily speedup two times Redis without resorting
# to pipelining nor sharding of the instance.
#
# By default threading is disabled, we suggest enabling it only in machines
# that have at least 4 or more cores, leaving at least one spare core.
# Using more than 8 threads is unlikely to help much. We also recommend using
# threaded I/O only if you actually have performance problems, with Redis
# instances being able to use a quite big percentage of CPU time, otherwise
# there is no point in using this feature.
#
# So for instance if you have a four cores boxes, try to use 2 or 3 I/O
# threads, if you have a 8 cores, try to use 6 threads. In order to
# enable I/O threads use the following configuration directive:
#
# io-threads 6


In reply to Michael Schneider

Re: Random "Unable to acquire a lock for caching" exception on Moodle 4.1

by Susana L. -
Picture of Particularly helpful Moodlers
Just want to share with you that because of the error "Unable to lock modinfo cache for course XXXX" that we used to have on error log file, we changed the coursemodinfo cahe store from memcached to the default store and since then we have no errors logged and no errors reported on UI...

On cache administration (https://[moodle]/cache/admin.php) for the "Area": coursemodinfo going to "Edit mappings" we changed to "None" to have the default_application instead of memcached.
Average of ratings: Useful (1)
In reply to Susana L.

Re: Random "Unable to acquire a lock for caching" exception on Moodle 4.1

by Alain Raap -
I see in our muc/config.php this section:

'definitionmappings' => array (
0 => array (
'store' => 'Redis',
'definition' => 'core/coursemodinfo',
'sort' => 1,
),
),
'locks' => array (
'cachelock_file_default' => array (
'name' => 'cachelock_file_default',
'type' => 'cachelock_file',
'dir' => 'filelocks',
'default' => true,
),
),

It seems to me that the locks are being written to the filesystem instead of to the caching server?
Or am I wrong? I was searching in the code for the error thrown, and I only found it in the 
caching module of file caching, that's why I am confused about these config settings.

Here's the code in the php file /[www root]/cache/locks/file/lib.php:

    public function lock($key, $ownerid, $block = false) {
        // Get the name of the lock file we want to use.
        $lockfile = $this->get_lock_file($key);

        // Attempt to create a handle to the lock file.
        // Mode xb is the secret to this whole function.
        //   x = Creates the file and opens it for writing. If the file already exists fopen returns false and a warning is thrown.
        //   b = Forces binary mode.
        $result = @fopen($lockfile, 'xb');

        // Check if we could create the file or not.
        if ($result === false) {
            // Lock exists already.
            if ($this->maxlife !== null && !array_key_exists($key, $this->locks)) {
                $mtime = filemtime($lockfile);
                if ($mtime < time() - $this->maxlife) {
                    $this->unlock($key, true);
                    $result = $this->lock($key, false);
                    if ($result) {
                        return true;
                    }
                }
            }
            if ($block) {
                // OK we are blocking. We had better sleep and then retry to lock.
                $iterations = 0;
                $maxiterations = $this->blockattempts;
                while (($result = $this->lock($key, false)) === false) {
                    // Usleep causes the application to cleep to x microseconds.
                    // Before anyone asks there are 1'000'000 microseconds to a second.
                    usleep(rand(1000, 50000)); // Sleep between 1 and 50 milliseconds.
                    $iterations++;
                    if ($iterations > $maxiterations) {
                        // BOOM! We've exceeded the maximum number of iterations we want to block for.
                        throw new cache_exception('ex_unabletolock');
                    }
                }
            }

            return false;
        } else {
            // We have the lock.
            fclose($result);
            $this->locks[$key] = $lockfile;
            return true;
        }
    }



In reply to Michael Schneider

Re: Random "Unable to acquire a lock for caching" exception on Moodle 4.1

by Alain Raap -
Michael are your still having problems with caching locks and are you also using Redis for caching?
In reply to Susana L.

Re: Random "Unable to acquire a lock for caching" exception on Moodle 4.1

by Stephan Robotta -
Picture of Core developers Picture of Particularly helpful Moodlers Picture of Peer reviewers Picture of Plugin developers
Hi,

we still experiencing the problem, however, it appears only for one specific user on a specific course (I assume - because the error is triggered via the search, when I used the same search with other users, the error did not show up - maybe because the course in question was not in the search results).
We are using 4.2.4 and Redis. Some of the issues mentioned in this thead should be solved in our version already.

The stacktrace is:
line 644 of /lib/modinfolib.php: moodle_exception thrown
line 478 of /lib/modinfolib.php: call to course_modinfo::build_course_cache()
line 436 of /lib/modinfolib.php: call to course_modinfo->__construct()
line 2578 of /lib/modinfolib.php: call to course_modinfo::instance()
line 800 of /search/classes/manager.php: call to get_fast_modinfo()
line 1075 of /search/classes/manager.php: call to core_search\manager->get_areas_user_accesses()
line 974 of /search/classes/manager.php: call to core_search\manager->search()
line 174 of /search/index.php: call to core_search\manager->paged_search()

An idea how to tackle down this error? Simply a purge cache did not solve the issue. It seems to be a general problem, maybe with that specific course only.
Thank you.