How does the session locks work in Moodle (part 1)?

The “problem” of session locking is not specific to Moodle. In general, the way web applications work is that any authenticated user will have his session data stored somehow on the server. At the beginnig of the HTTP request, his session data is retrieved and at the end of the request stored back.

What happens when the same user sends second request, before the first one finishes?

If PHP allowed the access to the same session for more than 1 request, then the data could easily get corrupted - by 2 separate processed reading & writing to it in parallel. So instead, the session is locked. The second request will get the session data only after the first requests finishes (and his session data is safely written).

To illustrate it - lets say we have 2 PHP scripts: sleep1.php and sleep2.php. They are exaclty the same and all they do is sleep for 5 seconds:

echo "Time start: " . date("H:i:s") . "<br />";
sleep(5);
echo "Time end: " . date("H:i:s") . "<br />";

When I run them in the browser, one after another, in separate browser tabs I get the results:

Time start: 20:11:17
Time end: 20:11:22
Time start: 20:11:18
Time end: 20:11:23

I have run the second tab 1 second after the first one, both took 5 seconds to finish. Simple.

Now I replace the code of both with a call to session_start():

echo "Time start: " . date("H:i:s") . "<br />";
session_start();
echo "After session_start(): " . date("H:i:s") . "<br />";
sleep(5);
echo "Time end: " . date("H:i:s") . "<br />";

And just like before I open sleep1.php in the first tab and sleep2.php second:

Time start: 20:25:33
After session_start(): 20:25:33
Time end: 20:25:38
Time start: 20:25:34
After session_start(): 20:25:38
Time end: 20:25:43

I clicked to open sleep1.php at 20:25:33. It has acquired the session immediately at 20:25:33 and then kept running until 20:25:38. Meanwhile, the second script was run at 20:25:34 but the call to session_start() has blocked it until 20:25:33 - exactly until the time the first script finished. Then, after getting the session, sleep1.php has run for 5 seconds until 20:25:43.

To alleviate the problem caused by the session lock, we can voluntarily release the lock before we finish the script. Imagine that during those 5 seconds (we sleep now - but let’s pretend this is some work done), we can write back to session what we need after the first 2 seconds.

Then, during the remaining 3 seconds we do some other processing, that we know will not need to update the user’s session. To release the lock earlier, we can use session_write_close().

Let’s extend our scripts:

echo "Time start: " . date("H:i:s") . "<br />";
session_start();
echo "After session_start(): " . date("H:i:s") . "<br />";
sleep(2);
session_write_close();
echo "After session_write_close(): " . date("H:i:s") . "<br />";
sleep(3);
echo "Time end: " . date("H:i:s") . "<br />";

The result now:

Time start: 16:28:24
After session_start(): 16:28:24
After session_write_close(): 16:28:26
Time end: 16:28:29
Time start: 16:28:25
After session_start(): 16:28:26
After session_write_close(): 16:28:28
Time end: 16:28:31

That’s better! Previously the time from start to end for script2.php was 9 seconds - 4 seconds waiting for the lock + 5 seconds of its own processing. Now the wait for the lock down to 1 second and script2.php run took 6 seconds. The second script gets the lock as soon as session_write_close() is called in the first one.

The session locking is sometimes problematic in applications like Moodle - because nearly all HTTP requests in Moodle come from authenticated users. Those users have the session created for them and therefore the locking described above affects them.

Move on to part 2.



How to delete several remote git branches?

Bash to the rescue - a quick and dirty way. First check what will be deleted - just echo the “git push…” commands. In the example below we will look for all the branches with OLD_BRANCH in the name.

git branch -r | grep OLD_BRANCH | cut -d'/' -f 2- | xargs -L 1 echo git push origin --delete

If everything looks OK, then actually run the commands:

git branch -r | grep OLD_BRANCH | cut -d'/' -f 2- | xargs -L 1 git push origin --delete

Install dependencies:

sudo apt build-dep wesnoth
sudo apt install libsdl2-dev libsdl2-image-dev libsdl2-mixer-dev libsdl2-ttf-dev libboost-all-dev libvorbis-dev libcairo2-dev libpango1.0-dev libssl-dev libreadline-dev cmake make scons pkgconf

Download the source code from https://wiki.wesnoth.org/Download, extract and compile.

tar -xf wesnoth-1.14.9.tar.bz2
cd wesnoth-1.14.9
scons

To play the game, you don’t need to install it, simply type in the same direcroty:

./wesnoth

Enjoy!


How many lines of code does Moodle core have?

The latest release - 3.4 has about 800k non-comment, non-blank lines of PHP code and about 90.7k non-comment, non-blank lines of JS code.

How did that change from version to version?

See the metrics from Moodle 2.6 to Moodle 3.4 for the PHP code:

Moodle_LOC_PHP

and for the JavaScript code:

Moodle_LOC_JS

How was that calculated?

To analyze the core Moodle I have removed from it: 3-rd party libraries, “build” and “lang” directories. I have then used cloc to calculate the number of non-comment and non-empty lines of code.


The problem

We have a typical web application that is deployed behind a load balancer with several web servers behind. The web servers are nearly identical - running the same OS, code, packages. But they do differ in one way - some have a quick access to the external asset’s repository. Other web servers do have the access as well but it is much slower. It looks something like this:

servers diagram

Moodle context

The web application is Moodle. It’s configured to use file system repository to allow access to the assets server. One of the web servers (web1) is in a co-located network with the fast access to the storage. Access from web2 and web3 is still possible (and configured but much slower). It would be benefictial if all the requests that trigger an access to the external file server were routed through web1 server. Practically it means that we want to send all requests to /repository/* scripts to web1.

The solution

HAProxy can do exactly what we need:

  • If a request is to http:///repository/* then route it to web1.
  • Let’s not compromise high availablility - in case our preferred web1 is down, send the request above to web2 or web3.
  • Send all the other requests to web1 (no point in making web1 dedicated for the repository-requests only), web2 or web3.

We start HAProxy configuration with the frontend section. Custom acl rule called below “url_file” will match the requests starting with the path /repository/. If acl condition is met, we send the request to backend called “file_servers”. Otherwise the request goes to the default backend called “all_servers”.

frontend http-in
	bind *:80

	acl url_file path_beg /repository/

	default_backend all_servers
	use_backend file_servers if url_file

The definition of our backend all_servers. Nothing really unusual here - just we send a little less (16 instead of 32) max conections to the web1 - as this one will be a bit more busy serving additional requests.

backend all_servers
	server web1 10.0.3.225:80 maxconn 16 check
	server web2 10.0.3.148:80 maxconn 32 check
	server web3 10.0.3.50:80 maxconn 32 check

In “file_servers” backend we want to use web1 server only, unless it’s down. Only then other web servers will take over - this is done with a “backup” option of HAProxy configuration:

backend file_servers
	server web1 10.0.3.225:80 maxconn 32 check
	server web2 10.0.3.148:80 maxconn 32 check backup
	server web3 10.0.3.50:80 maxconn 32 check backup

The configuration works as expected. The requests to http:///repository/repository_ajax.php are handled by web1. But when web1 is shut down, web2 and web3 are being used.


Apache service on Ubuntu 17.04 is configured by systemd with PrivateTmp=true option. You can see it in:

$ cat /etc/systemd/system/multi-user.target.wants/apache2.service
[Unit]
Description=The Apache HTTP Server
After=network.target remote-fs.target nss-lookup.target

[Service]
Type=forking
Environment=APACHE_STARTED_BY_SYSTEMD=true
ExecStart=/usr/sbin/apachectl start
ExecStop=/usr/sbin/apachectl stop
ExecReload=/usr/sbin/apachectl graceful
PrivateTmp=true
Restart=on-abort

[Install]
WantedBy=multi-user.target

This has some implications - as per documentation it “makes sharing between processes via /tmp or /var/tmp impossible”.

Basically /tmp and /var/tmp will be re-mounted for the apache process after it starts. During service restart directories will be cleaned up and re-created.

In the main filesystem they will be visible under something like: /tmp/systemd-private-3aa821d7448d4b21a2c379847aa20e20-apache2.service-0XM9bk

Let’s see it in action - I will find any of my apache processes running:

$ ps auxf | grep apache
root     11593  0.0  0.1 429640 36440 ?        Ss   15:15   0:00 /usr/sbin/apache2 -k start
www-data 11598  0.0  0.2 439860 83336 ?        S    15:15   0:05  \_ /usr/sbin/apache2 -k start

and query /proc for the mount information:

$ cat /proc/11598/mountinfo | grep /tmp
316 214 8:2 /tmp/systemd-private-3aa821d7448d4b21a2c379847aa20e20-apache2.service-0XM9bk/tmp /tmp rw,relatime shared:291 master:1 - ext4 /dev/sda2 rw,errors=remount-ro,data=ordered
317 214 8:2 /var/tmp/systemd-private-3aa821d7448d4b21a2c379847aa20e20-apache2.service-oKEULP/tmp /var/tmp rw,relatime shared:292 master:1 - ext4 /dev/sda2 rw,errors=remount-ro,data=ordered

$ cat /proc/11598/mounts | grep /tmp
/dev/sda2 /tmp ext4 rw,relatime,errors=remount-ro,data=ordered 0 0
/dev/sda2 /var/tmp ext4 rw,relatime,errors=remount-ro,data=ordered 0 0

And surely enough - a file “cli.html” created by the apache process is then visible for me as:

$ ls /tmp/systemd-private-3aa821d7448d4b21a2c379847aa20e20-apache2.service-0XM9bk/tmp
cli.html

There quite are few naming conventions for multiple-word variable names in use these days. The most popular are:

  • UpperCamelCase
  • lowerCamelCase
  • snake_case

There is also kebab-case convention used in LISP.

Moodle has adpoted a non-standard convention - all words are lower-case and glued together (moodlecase) - see Moodle docs. I don’t think there is a name for this convention.

It works quite well in some cases, e.g.

$isteacher
$launchurl

but it’s getting less readable with more words:

$oauthbodyhash
$truefeedbackimg
$maxcoursesinquery
$courseorsystemcontext

to finally become this:

$linkedcompetencypercentageformatted
$submissiongroupmemberswhoneedtosubmit
$proficientusercompetencyplanpercentageformatted

Compare how the above would look like using different conventions:

moodlecase camelCase snake_case
$isteacher $isTeacher $is_teacher
$launchurl $launchUrl $launch_url
$oauthbodyhash $oauthBodyHash $oauth_body_hash
$truefeedbackimg $trueFeedbackImg $true_feedback_img
$maxcoursesinquery $maxCoursesInQuery $max_courses_in_query
$courseorsystemcontext $courseOrSystemContext $course_or_system_context
$linkedcompetencypercentageformatted $linkedCompetencyPercentageFormatted $linked_competency_percentage_formatted
$proficientusercompetencyplanpercentageformatted $proficientUserCompetencyPlanPercentageFormatted $proficient_user_competency_plan_percentage_formatted

When mysqldump is created with –databases or –all-databases option, it will add “CREATE TABLE” and “USE” statements. If you need to restore the dump into different database (different name) you need to remove those statements. For small files it’s not a problem - just edit the dump with your favourite text editor. However huge MySQL dumps (e.g. gigabytes big) may be a challenge. Editing with vim means loading the wohle file into the memory - not a good idea.

Solutions:

Filter dump file with grep to ignore CREATE and USE lines on the fly, while restoring:

% egrep -v '^CREATE DATABASE |^USE ' big_mysql_dump.sql | mysql new_dbname

Use hexedit:

% hexedit big_mysql_dump.sql

Edit the file by overwriting CREATE and USE lines with spaces (so file size will not change). In hexedit use TAB to switch to ASCII editing, F2 to save, F10 to exit.

Use mysqldump-filter PHP script to do the same as above.

% git clone https://github.com/tmuras/mysqldump-filter
% cd mysqldump-filter
% ./mysqldump-edit.php -n big_mysql_dump.sql
String to overwrite at position 839:
-->CREATE DATABASE /*!32312 IF NOT EXISTS*/ `phpmyadmin` /*!40100 DEFAULT CHARACTER SET latin1 */;<--

String to overwrite at position 936:
-->USE `phpmyadmin`;<--
% ./mysqldump-edit.php big_mysql_dump.sql
Overwriten line at position 839:
-->CREATE DATABASE /*!32312 IF NOT EXISTS*/ `phpmyadmin` /*!40100 DEFAULT CHARACTER SET latin1 */;<--

Overwriten line at position 936:
-->USE `phpmyadmin`;<--

Sometimes we want to find out what has changed in the database when some application action was made. One very simple way to do that is to use MySQL data dump with “–skip-opt” option + diff. Of course if your database is very big, it may take a while. “–skip-opt” option will cause mysqldump to write one line with INSERT for each record - something we will need for diff to work well.

Here we go, the first snapshot:

% mysqldump -u root -p --skip-opt moodle31 > snapshot1.sql

Then I’ve opened my Moodle 3.1 installation and changed “Due date” in “Default assignment settings” - from 1 week to 2 weeks.

Second snapshot:

% mysqldump -u root -p --skip-opt moodle31 > snapshot2.sql

And simple diff:

% diff snapshot1.sql snapshot2.sql 
3957a3958
> INSERT INTO `mdl_config_log` VALUES (1014,2,1477218080,'assign','duedate','1209600','604800');
4718c4719
< INSERT INTO `mdl_config_plugins` VALUES (814,'assign','duedate','604800');
---
> INSERT INTO `mdl_config_plugins` VALUES (814,'assign','duedate','1209600');
13367c13368
< INSERT INTO `mdl_sessions` VALUES (4,0,'ob7ot4ngt6nddto7p5snvq3qb3',2,NULL,1477217567,1477217568,'127.0.0.1','127.0.0.1');
---
> INSERT INTO `mdl_sessions` VALUES (4,0,'ob7ot4ngt6nddto7p5snvq3qb3',2,NULL,1477217567,1477218080,'127.0.0.1','127.0.0.1');
15451c15452
< INSERT INTO `mdl_user` VALUES (2,'manual',1,0,0,0,1,'admin','$2y$10$p3IwPwFK9QAJumwKLj9mRe1MxaC3I1OUC1APcyCChcUFMMZIAmqrG','','Admin','User','nexor1984@gmail.com',0,'','','','','','','','','','','','','en','gregorian','','99',1476995496,1477217567,1476995496,1477217567,'127.0.0.1','',0,'','',1,1,0,1,1,0,0,1476995516,0,NULL,'','','','');
---
> INSERT INTO `mdl_user` VALUES (2,'manual',1,0,0,0,1,'admin','$2y$10$p3IwPwFK9QAJumwKLj9mRe1MxaC3I1OUC1APcyCChcUFMMZIAmqrG','','Admin','User','nexor1984@gmail.com',0,'','','','','','','','','','','','','en','gregorian','','99',1476995496,1477218080,1476995496,1477217567,'127.0.0.1','',0,'','',1,1,0,1,1,0,0,1476995516,0,NULL,'','','','');
16508c16509
< -- Dump completed on 2016-10-23 12:19:07
---
> -- Dump completed on 2016-10-23 12:21:59

We can see straight away that:

  • new record has been inserted into mdl_config_log
  • the value in mdl_config_plugins has changed from 604800 to 1209600
  • timestamps in mdl_sessions and mdl_user has been updated

Let’s make another test - let’s see what happens when we enable mobile web services in Moodle (I did that using Moodle UI between first and second snapshot).

% mysqldump -u root -p --skip-opt moodle31 > snapshot1.sql
% mysqldump -u root -p --skip-opt moodle31 > snapshot2.sql
% diff snapshot1.sql snapshot2.sql 
2492c2492
< INSERT INTO `mdl_config` VALUES (35,'enablewebservices','0');
---
> INSERT INTO `mdl_config` VALUES (35,'enablewebservices','1');
2901c2901
< INSERT INTO `mdl_config` VALUES (447,'enablemobilewebservice','0');
---
> INSERT INTO `mdl_config` VALUES (447,'enablemobilewebservice','1');
2918a2919
> INSERT INTO `mdl_config` VALUES (465,'webserviceprotocols','rest');
3955a3957
> INSERT INTO `mdl_config_log` VALUES (1013,2,1476995587,NULL,'enablemobilewebservice','1','0');
6446c6448
< INSERT INTO `mdl_external_services` VALUES (1,'Moodle mobile web service',0,NULL,0,'moodle',1476995420,1476995523,'moodle_mobile_app',1,1);
---
> INSERT INTO `mdl_external_services` VALUES (1,'Moodle mobile web service',1,NULL,0,'moodle',1476995420,1476995598,'moodle_mobile_app',1,1);
12876a12879
> INSERT INTO `mdl_role_capabilities` VALUES (1234,1,7,'webservice/rest:use',1,1476995587,2);
13359c13362
< INSERT INTO `mdl_sessions` VALUES (2,0,'t0ivjdjkmoo24jfar7ovrqbq31',2,NULL,1476995496,1476995566,'127.0.0.1','127.0.0.1');
---
> INSERT INTO `mdl_sessions` VALUES (2,0,'t0ivjdjkmoo24jfar7ovrqbq31',2,NULL,1476995496,1476995587,'127.0.0.1','127.0.0.1');
16499c16502
< -- Dump completed on 2016-10-20 22:33:01
---
> -- Dump completed on 2016-10-20 22:33:22