I ran into a race condition which generated a database warning on one of my pages, but firefox crashed before I hit submit on the bug report here.

Oh, I know, it might be in my logs. I'll go look.

The sequence of page loads that led to the race was:

1. load a page while logged in

(wait)

then roughly concurrently:
2. hit logout on that page
3. open a new tab and load the home page (configured to not point at "node" anymore) in that tab

I'll go look in the logs to see if I can get the exact error.

Support from Acquia helps fund testing for Drupal Acquia logo

Comments

Wesley Tanaka’s picture

Unfortunately, it seems like the logs only have the second warning (the one about headers already sent), but not the database one. It's not in my firefox disk cache either.

However, it seems that there's only one place in the codebase where an INSERT is called on the {sessions} table, in includes/session.inc.

That line generated a duplicate key warning.

Zen’s picture

Priority: Critical » Normal
Wesley Tanaka’s picture

Title: Race condition on inserting session into sessions table » Race condition in sess_read($key)

The bug is here:

  $result = db_query("SELECT u.*, s.* FROM {users} u INNER JOIN {sessions} s ON u.uid = s.uid WHERE s.sid = '%s'", $key);

  if (!db_num_rows($result)) {
    db_query("INSERT INTO {sessions} (sid, uid, hostname, timestamp) VALUES ('%s', 0, '%s', %d)", $key, $_SERVER["REMOTE_ADDR"], time());
    $result = db_query("SELECT u.* FROM {users} u WHERE u.uid = 0");
  }

Both SELECTs get run simultaneously, and return no results. Then both INSERTs get run with the same session id, and one of them generates an error.

jvandyk’s picture

I don't think I see a good solution to this. We could lock the session table every time we did a session read in case we need to do an insert before the second request did a read, but I imagine the performance hit on MyISAM would be unacceptable.

The error seems to have cropped up several times:

17825
21120

I don't understand why increasing the length of sid from 32 to 64 characters helped, as PHPSESSID's are always a 32 character md5 hash.

Wesley Tanaka’s picture

jvandyk,

Thanks for your contribution.

Neither 17825 nor 21120 appears to be referring to this race condition, which I don't even know exists or not in those earlier code bases. Forum post 21120 is an issue that occurred every time the user logged in, as opposed to this race condition, which does not appear all the time. Bug 17825 is an insertion of sid=0. It's extrememly improbable (or perhaps impossible) that such a session id would be generated and passed into sess_read.

Both also appear from the comments like they have been resolved. This issue has not been.

I don't think I see a good solution to this.

There are many solutions to this. Perhaps what you are saying is that you don't see any good solutions to this that could be encoded into a 2 or 3 line patch.

Wesley Tanaka’s picture

node_tag_new solves a similar race condition by prefixing the insert db_query with a '@'.

Wesley Tanaka’s picture

FileSize
708 bytes

This patch adds a '@' before the insert db_query, which I believe is supposed to suppress the warning that comes about if sess_read gets called twice simultaneously. Both simultaneously-run inserts i should be inserting the same values (time() for the two calls might be slightly different), in which case it is safe to ignore the duplicate insert warning.

Wesley Tanaka’s picture

Status: Active » Needs review
Wesley Tanaka’s picture

s/inserts i should/inserts should/

markus_petrux’s picture

I'm not sure to understand the problem. According to the PHP manual:
http://www.php.net/session_write_close

Session data is usually stored after your script terminated without the need to call session_write_close(), but as session data is locked to prevent concurrent writes only one script may operate on a session at any time. When using framesets together with sessions you will experience the frames loading one by one due to this locking. You can reduce the time needed to load all the frames by ending the session as soon as all changes to session variables are done.

markus_petrux’s picture

An interesting bug report "Session (concurrency ?) problem", marked as bogus.

[20 Jul 2001 8:30am CEST] kalowsky@php.net
Comments on the php-dev list, by Sascha Schumann:

> This "solved" the problem and I concluded the bug was only due to my fault
> : I should have locked my session table (or row...) to avoid race
> conditions and concurrency problems.

That is right. The session storage handlers have to perform locking themselves, if they are supposed to be suited for concurrent accesses.

hmmm...

Dries’s picture

Maybe session_write_close() holds a lock. Clearly, session_read() does not. :)

markus_petrux’s picture

I believe part of the solution would be to rewrite the session handlers. Probably helps moving the access to the user record off these session handlers.

rkerr’s picture

Why do we do inserts in sess_read, instead of sess_open?

rkerr’s picture

Title: Race condition in sess_read($key) » Optimize session handling and eliminate race condition in sess_read
FileSize
3.68 KB

Went through this with moshe, and figured that we probably shouldn't be doing any database writes in sesss_read. This patch should avoid the race condition by doing the db inserts in the "proper" place (sess_write), as well as optimizing sessions for anonymous users by only creating session data for them when there is _really_ some data to be stored (not just messages).

It doesn't seem to break any functionality :) and supports a user transitioning from being not logged in to logged in and maintaining their session data (not completely sure if that happened before or not).

Please review and test!

moshe weitzman’s picture

Assigned: Unassigned » moshe weitzman
FileSize
4.27 KB

Broke out a query in sess_read() to speed things up a little for anon users. Added some code comments.

This patch represents a massive speedup and memory improvement for Drupal. The sessions table will get much smaller, and we avoid an expensive insert for most anon users. Yet we offer anon sessions when a module wants to use them (e.g. comment control panel).

Dries’s picture

Status: Needs review » Fixed

Tested. Committed to HEAD. Great patch.

moshe weitzman’s picture

Status: Fixed » Active

I added some module updating info to http://drupal.org/node/22218#sessions. Also, this patch broke the user block where we report the number of anon users currently on the site. I plan to remove that info from the block, unless someone comes up with a better solution.

moshe weitzman’s picture

Status: Active » Needs review
FileSize
1.26 KB

In addiiton to Who's Online, we crippled the throttle module. So i'm scaling back the optimization. This patch records session records for anon users too. The only exception are anon users without cookies. Those get no session record unless a module requests it. This helps keep crawlers from spawning thousands of useless sessions.

killes@www.drop.org’s picture

Can't we make throttle module and the user block specifically request a session for anon users with cookies? I don't use neither the block not the module and would want to have the complete optimization.

Dries’s picture

I committed Moshe's last patch but am not marking this fixed yet. Maybe a better solution arises. Also, it looks like that if-test could be simplified now?

Wesley Tanaka’s picture

So what's the consensus on putting a '@' before the insert db_query call?

Cvbge’s picture

So what's the consensus on putting a '@' before the insert db_query call?

Using @db_query() does nothing. You can test this by creating simple table with unique column and then creating a block with php code which does inserts a value. On second refresh you'll still see the error.

This is due to this http://pl2.php.net/manual/en/function.set-error-handler.php:

It is important to remember that the standard PHP error handler is completely bypassed. error_reporting() settings will have no effect and your error handler will be called regardless - however you are still able to read the current value of error_reporting and act appropriately. Of particular note is that this value will be 0 if the statement that caused the error was prepended by the @ error-control operator.

So we'd have to check error_reporting inside of error_handler.

markus_petrux’s picture

So we'd have to check error_reporting inside of error_handler.

Oh, yes, please do.

See this:
http://drupal.org/node/41209

moshe weitzman’s picture

Status: Needs review » Fixed
Wesley Tanaka’s picture

Status: Fixed » Active

via inspection of session.inc 1.26, the originally reported problem has not been addressed

moshe weitzman’s picture

Priority: Normal » Minor
Status: Active » Fixed

we fixed a more serious race condition. the one you mention requires multiple simultaneous browser windows with a logout action. extremely rare to the point of "not worth it". moving back to fixed since we did improve session hadnling a lot and i don't want this issue permanently logged as won't fix.

Wesley Tanaka’s picture

Title: Optimize session handling and eliminate race condition in sess_read » Optimize session handling
Priority: Minor » Normal

This is the problem with one issue report meaning two different things.

Split the issue. This issue is retroactively for tracking the patches that have already been committed.

http://drupal.org/node/52662 is for the race condition. Let's move the discussion about that issue's status there.

Anonymous’s picture

Status: Fixed » Closed (fixed)