Issue #1306 new

test_2_File_Concurrency fails intermittently

Nathan Kinder
created an issue

I've noticed intermittent failures of the test_2_File_Concurrency test in test_session.py. I'm using a recent checkout from the default branch (CherryPy 3.2.5 plus whatever has been committed since) with Python 2.7.5.

The failures can be seen by simply running the test_session.py tests in a loop as follows:

  for i in `seq 1 100`; do nosetests -s ./test_session.py; done

I'm seeing failures about 5% of the time. Here is an example of the failure output:

S..........
----------------------------------------------------------------------
Ran 11 tests in 10.387s

OK (SKIP=1)
S...F......
======================================================================
FAIL: test_2_File_Concurrency (cherrypy.test.test_session.SessionTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/nathank/Source/cherrypy/cherrypy/cherrypy/test/test_session.py", line 218, in test_2_File_Concurrency
    self._test_Concurrency()
  File "/home/nathank/Source/cherrypy/cherrypy/cherrypy/test/test_session.py", line 268, in _test_Concurrency
    self.assertEqual(hitcount, expected)
AssertionError: 150 != 151
-------------------- >> begin captured logging << --------------------
cherrypy.error: INFO: [19/Mar/2014:14:41:18] ENGINE Stopped thread 'Session cleanup'.
cherrypy.access.49232208: INFO: 127.0.0.1 - - [19/Mar/2014:14:41:18] "GET /setsessiontype/file HTTP/1.1" 200 - "" ""
cherrypy.error: INFO: [19/Mar/2014:14:41:18] ENGINE Started monitor thread 'Session cleanup'.
cherrypy.access.49232208: INFO: 127.0.0.1 - - [19/Mar/2014:14:41:18] "GET / HTTP/1.1" 200 1 "" ""
cherrypy.access.49232208: INFO: 127.0.0.1 - - [19/Mar/2014:14:41:18] "GET / HTTP/1.1" 200 1 "" ""
...
cherrypy.access.49232208: INFO: 127.0.0.1 - - [19/Mar/2014:14:41:20] "GET / HTTP/1.1" 200 3 "" ""
cherrypy.access.49232208: INFO: 127.0.0.1 - - [19/Mar/2014:14:41:20] "GET / HTTP/1.1" 200 3 "" ""
--------------------- >> end captured logging << ---------------------

----------------------------------------------------------------------
Ran 11 tests in 10.406s

FAILED (SKIP=1, failures=1)
S..........
----------------------------------------------------------------------
Ran 11 tests in 10.505s

OK (SKIP=1)

This looks very similar to ticket #799, which was resolved long ago.

Comments (2)

  1. Nathan Kinder reporter

    I've been able to see that this is a race condition by instrumenting the test. When a failure occurs, I will see that the same counter value is returned for subsequent requests. It seems like the request is not being locked between getting the current counter value from the session data and setting the new incremented value:

    def index(self):
                sess = cherrypy.session
                c = sess.get('counter', 0) + 1
                time.sleep(0.01)
                sess['counter'] = c
                return str(c)
    

    My understanding is that the request is supposed to be locked, but it seems like that isn't happening.

  2. Nathan Kinder reporter

    Here is an example of the instrumented log output during the test run. This first snippet shows things working correctly:

    cherrypy.access.40446288: INFO: 127.0.0.1 - - [21/Mar/2014:03:45:41] "GET / HTTP/1.1" 200 1 "" ""
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:41] TOOLS.SESSIONS Set id to cb3c07632b6e6afdb47c83e25f6996c97e9cea13.
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:41] TOOLS.SESSIONS Lock acquired.
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:41]  in FileSession._load
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:41]  got session data 3
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:41]  in FileSession._save
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:41] TOOLS.SESSIONS Lock released.
    cherrypy.access.40446288: INFO: 127.0.0.1 - - [21/Mar/2014:03:45:41] "GET / HTTP/1.1" 200 1 "" ""
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:41] TOOLS.SESSIONS Set id to cb3c07632b6e6afdb47c83e25f6996c97e9cea13.
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:41] TOOLS.SESSIONS Lock acquired.
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:41]  in FileSession._load
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:41]  got session data 4
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:41]  in FileSession._save
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:41] TOOLS.SESSIONS Lock released.
    cherrypy.access.40446288: INFO: 127.0.0.1 - - [21/Mar/2014:03:45:41] "GET / HTTP/1.1" 200 1 "" ""
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:41] TOOLS.SESSIONS Set id to cb3c07632b6e6afdb47c83e25f6996c97e9cea13.
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:41] TOOLS.SESSIONS Lock acquired.
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:41]  in FileSession._load
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:41]  got session data 5
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:41]  in FileSession._save
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:41] TOOLS.SESSIONS Lock released.
    

    This snippet shows how things get out of order when a failure occurs:

    cherrypy.access.40446288: INFO: 127.0.0.1 - - [21/Mar/2014:03:45:42] "GET / HTTP/1.1" 200 2 "" ""
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42] TOOLS.SESSIONS Set id to cb3c07632b6e6afdb47c83e25f6996c97e9cea13.
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42] TOOLS.SESSIONS Lock acquired.
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42]  in FileSession._load
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42]  got session data 34
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42]  in FileSession._save
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42] TOOLS.SESSIONS Lock released.
    cherrypy.access.40446288: INFO: 127.0.0.1 - - [21/Mar/2014:03:45:42] "GET / HTTP/1.1" 200 2 "" ""
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42] TOOLS.SESSIONS Lock acquired.
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42]  in FileSession._load
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42]  got session data 35
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42] TOOLS.SESSIONS Set id to cb3c07632b6e6afdb47c83e25f6996c97e9cea13.
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42] TOOLS.SESSIONS Lock acquired.
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42]  in FileSession._load
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42]  got session data 35
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42]  in FileSession._save
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42] TOOLS.SESSIONS Lock released.
    cherrypy.access.40446288: INFO: 127.0.0.1 - - [21/Mar/2014:03:45:42] "GET / HTTP/1.1" 200 2 "" ""
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42]  in FileSession._save
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42] TOOLS.SESSIONS Set id to cb3c07632b6e6afdb47c83e25f6996c97e9cea13.
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42] TOOLS.SESSIONS Lock released.
    cherrypy.access.40446288: INFO: 127.0.0.1 - - [21/Mar/2014:03:45:42] "GET / HTTP/1.1" 200 2 "" ""
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42] TOOLS.SESSIONS Lock acquired.
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42]  in FileSession._load
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42]  got session data 36
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42] TOOLS.SESSIONS Set id to cb3c07632b6e6afdb47c83e25f6996c97e9cea13.
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42] TOOLS.SESSIONS Lock acquired.
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42]  in FileSession._load
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42]  got session data 36
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42]  in FileSession._save
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42] TOOLS.SESSIONS Lock released.
    cherrypy.access.40446288: INFO: 127.0.0.1 - - [21/Mar/2014:03:45:42] "GET / HTTP/1.1" 200 2 "" ""
    cherrypy.error.40446288: INFO: [21/Mar/2014:03:45:42]  in FileSession._save
    

    You can see that the session data that is retrieved repeats the same value, when it should be incremented for every request.

  3. Log in to comment