Issue #1199 resolved

test_file_stream fails intermittently

Jason R. Coombs
created an issue

I'm finding on Windows 8, Python 2.7.3 64-bit, test_file_stream will fail intermittently (about .5) with output similar to this:

[env] PS C:\Users\jaraco\projects\public\cherrypy> nosetests -s -v -x cherrypy.test.test_static
testStatic (cherrypy.test.test_static.StaticTest) ... ok
test_755_vhost (cherrypy.test.test_static.StaticTest) ... ok
test_config_errors (cherrypy.test.test_static.StaticTest) ... ok
test_fallthrough (cherrypy.test.test_static.StaticTest) ... ok
test_file_stream (cherrypy.test.test_static.StaticTest) ... FAIL

======================================================================
FAIL: test_file_stream (cherrypy.test.test_static.StaticTest)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\Users\jaraco\projects\public\cherrypy\cherrypy\test\test_static.py",
line 258, in test_file_stream
    expected)
AssertionError: The file should have advanced to position 262144, but has already advanced to the end of the file. It may not be streamed as intended, or at the wrong chunk size (64k)
-------------------- >> begin captured logging << --------------------
cherrypy.access.49064984: INFO: 127.0.0.1 - - [26/Dec/2012:09:22:22] "GET /bigfile HTTP/1.1" 200 1048576 "" ""
cherrypy.access.49064984: INFO: 127.0.0.1 - - [26/Dec/2012:09:22:22] "GET /tell
HTTP/1.1" 200 6 "" ""
cherrypy.access.49064984: INFO: 127.0.0.1 - - [26/Dec/2012:09:22:22] "GET /tell
HTTP/1.1" 200 6 "" ""
cherrypy.access.49064984: INFO: 127.0.0.1 - - [26/Dec/2012:09:22:22] "GET /tell
HTTP/1.1" 200 6 "" ""
cherrypy.access.49064984: INFO: 127.0.0.1 - - [26/Dec/2012:09:22:22] "GET /tell
HTTP/1.1" 200 - "" ""
--------------------- >> end captured logging << ---------------------

----------------------------------------------------------------------
Ran 5 tests in 10.408s

FAILED (failures=1)

The 'expected' number reported varies, but I've seen it between 192k and 384k. When it fails, if I'm running a debugger, b is '', which according to the comments means "The file was closed on the server." I don't know why that would be. Can someone help shore up this test so it's more robust?

Comments (6)

  1. EliAndrewC

    I also see this on Ubuntu 10.10 with Python 2.7.3:

    eli@haku:~/cherrypy/cherrypy/test$ nosetests -s test_static.py:StaticTest.test_file_stream
    F
    ======================================================================
    FAIL: test_file_stream (cherrypy.test.test_static.StaticTest)
    ----------------------------------------------------------------------
    Traceback (most recent call last):
      File "/home/eli/cherrypy/cherrypy/test/test_static.py", line 258, in test_file_stream
        expected)
    AssertionError: The file should have advanced to position 458752, but has already advanced to the end of the file. It may not be streamed as intended, or at the wrong chunk size (64k)
    -------------------- >> begin captured logging << --------------------
    cherrypy.error: INFO: [30/Mar/2013:14:08:52] ENGINE Listening for SIGHUP.
    cherrypy.error: INFO: [30/Mar/2013:14:08:52] ENGINE Listening for SIGTERM.
    cherrypy.error: INFO: [30/Mar/2013:14:08:52] ENGINE Listening for SIGUSR1.
    cherrypy.test.helper: INFO: Python version used to run this test script: 2.7.3
    cherrypy.test.helper: INFO: CherryPy version: 3.2.4
    cherrypy.test.helper: INFO: HTTP server version: HTTP/1.1
    cherrypy.test.helper: INFO: PID: 6076
    cherrypy.error: INFO: [30/Mar/2013:14:08:52] ENGINE Bus STARTING
    cherrypy.error: INFO: [30/Mar/2013:14:08:52] ENGINE Started monitor thread '_TimeoutMonitor'.
    cherrypy.error: INFO: [30/Mar/2013:14:08:52] ENGINE Serving on http://127.0.0.1:54583
    cherrypy.error: INFO: [30/Mar/2013:14:08:52] ENGINE Bus STARTED
    cherrypy.access.38403664: INFO: 127.0.0.1 - - [30/Mar/2013:14:08:52] "GET /bigfile HTTP/1.1" 200 1048576 "" ""
    cherrypy.access.38403664: INFO: 127.0.0.1 - - [30/Mar/2013:14:08:52] "GET /tell HTTP/1.1" 200 6 "" ""
    cherrypy.access.38403664: INFO: 127.0.0.1 - - [30/Mar/2013:14:08:52] "GET /tell HTTP/1.1" 200 6 "" ""
    cherrypy.access.38403664: INFO: 127.0.0.1 - - [30/Mar/2013:14:08:52] "GET /tell HTTP/1.1" 200 6 "" ""
    cherrypy.access.38403664: INFO: 127.0.0.1 - - [30/Mar/2013:14:08:52] "GET /tell HTTP/1.1" 200 6 "" ""
    cherrypy.access.38403664: INFO: 127.0.0.1 - - [30/Mar/2013:14:08:52] "GET /tell HTTP/1.1" 200 6 "" ""
    cherrypy.access.38403664: INFO: 127.0.0.1 - - [30/Mar/2013:14:08:52] "GET /tell HTTP/1.1" 200 6 "" ""
    cherrypy.access.38403664: INFO: 127.0.0.1 - - [30/Mar/2013:14:08:52] "GET /tell HTTP/1.1" 200 7 "" ""
    --------------------- >> end captured logging << ---------------------
    
    ----------------------------------------------------------------------
    Ran 1 test in 5.151s
    
    FAILED (failures=1)
    

    I should note that it usually passes when run on its own like that, but has so far always failed when run along with the other tests in test_static.py in case that helps.

  2. Barry Warsaw

    I'm not so sure this bug is fixed. I've run into it while running the test suite during package build on Debian.

    ======================================================================
    FAIL: test_file_stream (cherrypy.test.test_static.StaticTest)
    ----------------------------------------------------------------------
    Traceback (most recent call last):
      File "/tmp/adt-run.asVKDS/dsc0-build/cherrypy3-3.5.0/cherrypy/test/test_static.py", line 289, in test_file_stream
        "chunk size (64k)" % read_so_far)
    nose.proxy.AssertionError: The file should have advanced to position 983040, but has already advanced to the end of the file. It may not be streamed as intended, or at the wrong chunk size (64k)
    

    How can I help you fix this? For now, I'm going to disable the test crash.

  3. Log in to comment