Session changes in Mahara 15.04 can cause excessively large response headers

[Aaron Wells]

For the new Ajax progress bar, Bug 1352028, we changed htdocs/auth/session.php so that it closes the PHP session when not in use. This was necessary in order to allow multiple requests to the same session to process simultaneously; PHP by default locks the session between the time you call session_start() and session_write_close().

The downside to this approach, though, is that every time you call session_start(), PHP adds a new (duplicate) PHP_SESS_ID cookie to the request header. Since we open and close the session every time we call $SESSION->set() now, this can lead to a very large cookie header. (See https://bugs.php.net/bug.php?id=38104 )

On our hosting environment, these headers got too large and started causing our Nginx proxy server to throw errors while trying to initiate an MNet connection. This causes the proxy server to throw a 500 error, and to log an error like this:

2015/04/20 14:59:03 [error] 14845#0: *137093286 upstream sent too big header while reading response header from upstream, client: 2404:130:0:1000:61f4:7e47:8a26:821, server: master-mahara.catalystdemo.net.nz, request: "GET /auth/xmlrpc/land.php?token=3acfeeb7cad9814471ec5932fc293b30bbc7e387&idp=http://mnet-moodle.testing.elearning.catalyst.net.nz&wantsurl= HTTP/1.1", upstream: "http://202.78.243.12:9226/auth/xmlrpc/land.php?token=3acfeeb7cad9814471ec5932fc293b30bbc7e387&idp=http://mnet-moodle.testing.elearning.catalyst.net.nz&wantsurl=", host: "master-mahara.catalystdemo.net.nz"

[Aaron Wells (u-aaronw)]

As a workaround, reverting the changes to htdocs/auth/session.php corrects the problem:

git checkout 55a8deb8cb~ -- htdocs/auth/session.php

This will cause the ajax status bar to not load properly, and it will cause the ajax block loader to load blocks in serial instead of in parallel, but otherwise it causes no problems. You can disable the ajax block loader by adding "$cfg->ajaxifyblocks = false;" to your config.php file, which will turn off the ajax block loader and prevent that problem.

So far I have only noticed this problem popping up while doing an mnet connection, and only on our proxied hosting cluster (not on my local machine). It's possible that MNet sets a lot of session values, thus causing the problem to be worse than normal. It's also possible that our hosting cluster has tighter response header limitations than my local machine. However, the potential exists for this to cause problems in other areas and other hosting setups as well, so I've marked it "Critical".

[Aaron Wells (u-aaronw)]

So, after that patch was added, most pages in Mahara only add one or two copies of the session cookie to the header. Admin section pages add at least 5, perhaps because of all the checking to make sure you're an admin.

The Mnet landing page adds 102 copies of the session cookie! That's over 7000 characters, 7KB. This is indeed a bit larger than you'd expect an HTTP response header to be.

I'm going to have to look into some way to mitigate this. There are two main possibilities:

1. Find some workaround to the PHP bug that causes PHP to send a duplicate copy of the session header every time you do session_start()

2. OR, stop switching the session on and off when there is no need to do so. The reason we do that, is so that JSON scripts can run asynchronously, without having to wait for other scripts to finish using the session. But there are other possibilities, like asking developers to manually close the session if they're expecting to use AJAX.

3. OR, reduce the number of times we open & close the PHP session. Currently, we open/close it each time we do $SESSION->set(), $SESSION->unset(), $SESSION->clear(), or write messages to the logs. It's unclear which of these the MNet is doing so much of (I'll need to add some additional logging to check on that), but perhaps we could do bulk writes, and/or put the log messages into a DB table instead of the session.

[Aaron Wells (u-aaronw)]

Having looked through it some more, it looks quite unlikely that PHP is going to fix this bug. They've closed a couple of bug reports about it, saying that you shouldn't open and close the session like this anyway, because it can cause race conditions. Which is true, but based on the kinds of things we store in the database, I don't think it's a particularly big danger for us.

I ran some tests and found that every time you call session_start(), it refreshes $_SESSION with the latest contents from the session store. So, having asynchronous scripts that write to session in the way we do (bookended by session_start() and session_write_close()) pretty much works out.

The only problem is that bug with sessid. I'm looking into a couple of workarounds. One (hacky) solution would be to use headers_list() and header_remove() to detect the multiple session headers and remove them. This would need to be done *before* the headers get sent, so perhaps in the call to smarty().

Another possibility is to use the SessionHandler class to manually open and close the session without running session_start(): http://php.net/manual/en/class.sessionhandler.php

The downside to this, is that it requires PHP 5.4, so we'd have to raise our minimum supported version. On the other hand, support for PHP 5.3 ended in August 2014 (and support for 5.4 is ending in September 2015!) so perhaps its time we upped our minimum PHP version anyhow.

[Aaron Wells (u-aaronw)]

On the third hand, we really shouldn't be changing support versions in a minor release (which 15.04.1 will be), so perhaps for 15.04.1 the hacky header-sniffing fix is the way to go...

[Aaron Wells (u-aaronw)]

After discussing this with Robert and some other folks, here are my conclusions:

1. For Mahara 15.10dev, we raise the minimum required PHP version to 5.4.

2. For Mahara 15.04, we keep it at 5.3 (so that we don't strand anyone who upgraded their Mahara to 15.04.0)

3. In 15.04.1, we add the PHP 5.4 code that uses SessionHandler to directly manipulate the session without calling session_start(). We put a wrapper around this that only calls the code if you have PHP 5.4 installed.

4. For the people who are on 15.04.1 and still on PHP 5.3, we just stop switching the sessions on and off. This means that the AJAX block loader will load blocks one at a time instead of in parallel, and it will also mean that the experimental bulk CSV exporter progress bar won't update in real-time, but neither of those is a showstopper.

[Mahara Bot (dev-mahara)]

Patch for "master" branch: https://reviews.mahara.org/4690

[Aaron Wells (u-aaronw)]

On further research, it looks like directly manipulating the session through SessionHandler isn't going to work. If you're using the default session handler it causes a fatal error. If you're using a custom session handler, like memcached, then it doesn't throw a fatal error, but it doesn't seem to work as expected.

So we can ignore all the stuff in the preceding comment. We probably should raise our minimum supported PHP version to 5.4, but not because of this.

What I've done instead, is after each time we call session_start(), I call a method that uses headers_list() and header_remove() to eliminate the duplicate session cookies.

The behavior of PHP in this regard is a bit buggy. When there are duplicate session cookies that are going to be sent out, it still only shows one copy of the session cookie when you call headers_list(). However, doing "header_remove('Set-Cookie')" will remove all of the session cookie headers (as well as all the other cookies). So what I do is use headers_list() to get a list of all the unique cookies, do header_remove('Set-Cookie'), and then use header() to add each cookie header back.

[Aaron Wells (u-aaronw)]

Testing instructions:

The easiest way to test this is to inspect the raw HTTP response headers, using the network tab of Firefox's "Web Developer" feature (Tools -> Web Developer -> Network) or Chromium's "Developer Tools" feature (Menu -> More Tools -> Developer Tools, then click the Network tab).

1. Open up the network tab so you can see the individual HTTP requests being sent by your browser.
2. Log in to your Mahara site as an admin
3. Go to the Mahara Administration page.
4. Look at the response headers for the HTTP request for /admin/index.php (it'll be at the top of a long list of HTTP requests as your browser requests copies of all the page's assets)
5. Locate the "Set-Cookie" response header

Expected result: One copy of the "mahara" session cookie, and possibly a couple of other cookies like "lastinstitution". Like this:

Set-Cookie: "mahara=77e26f14610b4c998cc070f415d74136; path=/mahara/htdocs/; HttpOnly"

Bug result: Multiple copies of the "mahara" session cookie. In Chromium this will show up as multiple identical Set-Cookie headers. In Firefox this will show up as one very long Set-Cookie header with repeated data, like this:

Set-Cookie: "mahara=8d5b3e057f485394554cff20ef1cfd62; path=/mahara/htdocs/; HttpOnlymahara=8d5b3e057f485394554cff20ef1cfd62; path=/mahara/htdocs/; HttpOnlymahara=8d5b3e057f485394554cff20ef1cfd62; path=/mahara/htdocs/; HttpOnlymahara=8d5b3e057f485394554cff20ef1cfd62; path=/mahara/htdocs/; HttpOnlymahara=8d5b3e057f485394554cff20ef1cfd62; path=/mahara/htdocs/; HttpOnly"

[Mahara Bot (dev-mahara)]

Reviewed: https://reviews.mahara.org/4690
Committed: http://gitorious.org/mahara/mahara/commit/390a676734de8379a68d0c91e5257a6dcc61f48b
Submitter: Robert Lyon (<email address hidden>)
Branch: master

commit 390a676734de8379a68d0c91e5257a6dcc61f48b
Author: Aaron Wells <email address hidden>
Date: Thu Apr 23 18:26:35 2015 +1200

Clear out duplicate session cookies created by calls to session_start()

Bug 1446036

Change-Id: I7f59b8c295a2ba6c2ffeca7bdab8899fef09bb0f

[Mahara Bot (dev-mahara)]

Patch for "15.04_STABLE" branch: https://reviews.mahara.org/4709

[Mahara Bot (dev-mahara)]

Reviewed: https://reviews.mahara.org/4709
Committed: http://gitorious.org/mahara/mahara/commit/607563234d9e9271e826edd20630b973e2d8ebc6
Submitter: Robert Lyon (<email address hidden>)
Branch: 15.04_STABLE

commit 607563234d9e9271e826edd20630b973e2d8ebc6
Author: Aaron Wells <email address hidden>
Date: Thu Apr 23 18:26:35 2015 +1200

Clear out duplicate session cookies created by calls to session_start()

Bug 1446036

Change-Id: I7f59b8c295a2ba6c2ffeca7bdab8899fef09bb0f