Previously, newly merged Ceilometer code broke my test to throw a sorting error when there is no index. After jd's patch "Change Ia2ff201c: Disable mongod prealloc, wait for it to start" was merged (+ possibly other changes), seems like my test is working again. If I make the test database 15000 times larger, I do get a sorting error and it take…

sorting-error-database-x-15000.txt

$ tox -e py27 -- tests.storage.test_impl_mongodb.RawSampleTest.test_get_samples_in_default_order
GLOB sdist-make: /opt/stack/ceilometer/setup.py
py27 inst-nodeps: /opt/stack/ceilometer/.tox/dist/ceilometer-2013.2.a263.g33b691f.zip
py27 runtests: commands[0] | bash -x /opt/stack/ceilometer/run-tests.sh tests.storage.test_impl_mongodb.RawSampleTest.test_get_samples_in_default_order
WARNING:test command found but not installed in testenv
  cmd: /bin/bash
  env: /opt/stack/ceilometer/.tox/py27
Maybe forgot to specify a dependency?
+ set -e
+ '[' tests.storage.test_impl_mongodb.RawSampleTest.test_get_samples_in_default_order = --coverage ']'
+ '[' '!' '' ']'
+ bash tools/init_testr_if_needed.sh
+ python setup.py testr --slowest '--testr-args=--concurrency=1 --here=nova_tests tests.storage.test_impl_mongodb.RawSampleTest.test_get_samples_in_default_order'
running testr
running=${PYTHON:-python} -m subunit.run discover -t ./nova_tests ./nova_tests --list 
PASSED (id=72)
Slowest Tests
Test id                                                                          Runtime (s)
-------------------------------------------------------------------------------  -----------
tests.storage.test_impl_mongodb.RawSampleTest.test_get_samples_in_default_order  256.869
++ mktemp -d
+ MONGO_DATA=/tmp/tmp.JrFx5PgGv5
+ trap clean_exit EXIT
+ mkfifo /tmp/tmp.JrFx5PgGv5/out
+ MONGO_PID=14029
+ mongod --maxConns 32 --noprealloc --smallfiles --quiet --noauth --port 29000 --dbpath /tmp/tmp.JrFx5PgGv5 --bind_ip localhost
+ read line
+ grep -q 'waiting for connections on port'
+ echo 'note: noprealloc may hurt performance in many applications'
+ read line
+ echo 'Wed Jul 24 05:28:04.083 [initandlisten] MongoDB starting : pid=14029 port=29000 dbpath=/tmp/tmp.JrFx5PgGv5 64-bit host=precise64'
+ grep -q 'waiting for connections on port'
+ read line
+ grep -q 'waiting for connections on port'
+ echo 'Wed Jul 24 05:28:04.085 [initandlisten] db version v2.4.5'
+ read line
+ grep -q 'waiting for connections on port'
+ read line
+ echo 'Wed Jul 24 05:28:04.085 [initandlisten] build info: Linux ip-10-2-29-40 2.6.21.7-2.ec2.v1.2.fc8xen #1 SMP Fri Nov 20 17:48:28 EST 2009 x86_64 BOOST_LIB_VERSION=1_49'
+ grep -q 'waiting for connections on port'
+ read line
+ grep -q 'waiting for connections on port'
+ read line
+ echo 'Wed Jul 24 05:28:04.085 [initandlisten] options: { bind_ip: "localhost", dbpath: "/tmp/tmp.JrFx5PgGv5", maxConns: 32, noauth: true, noprealloc: true, port: 29000, quiet: true, smallfiles: true }'
+ grep -q 'waiting for connections on port'
+ read line
+ echo 'Wed Jul 24 05:28:04.103 [initandlisten] journal dir=/tmp/tmp.JrFx5PgGv5/journal'
+ grep -q 'waiting for connections on port'
+ read line
+ grep -q 'waiting for connections on port'
+ echo 'Wed Jul 24 05:28:04.103 [initandlisten] recover : no journal files present, no recovery needed'
+ read line
+ grep -q 'waiting for connections on port'
+ echo 'Wed Jul 24 05:28:04.944 [initandlisten] preallocateIsFaster=true 15.6'
+ read line
+ echo 'Wed Jul 24 05:28:05.377 [initandlisten] preallocateIsFaster=true 7.62'
+ grep -q 'waiting for connections on port'
+ read line
+ grep -q 'waiting for connections on port'
+ echo 'Wed Jul 24 05:28:06.934 [initandlisten] preallocateIsFaster=true 9.62'
+ read line
+ grep -q 'waiting for connections on port'
+ echo 'Wed Jul 24 05:28:06.934 [initandlisten] preallocating a journal file /tmp/tmp.JrFx5PgGv5/journal/prealloc.0'
+ read line
+ grep -q 'waiting for connections on port'
+ echo 'Wed Jul 24 05:28:07.322 [initandlisten] preallocating a journal file /tmp/tmp.JrFx5PgGv5/journal/prealloc.1'
+ read line
+ grep -q 'waiting for connections on port'
+ echo 'Wed Jul 24 05:28:07.663 [initandlisten] preallocating a journal file /tmp/tmp.JrFx5PgGv5/journal/prealloc.2'
+ read line
+ echo 'Wed Jul 24 05:28:08.016 [FileAllocator] allocating new datafile /tmp/tmp.JrFx5PgGv5/local.ns, filling with zeroes...'
+ grep -q 'waiting for connections on port'
+ read line
+ grep -q 'waiting for connections on port'
+ echo 'Wed Jul 24 05:28:08.016 [FileAllocator] creating directory /tmp/tmp.JrFx5PgGv5/_tmp'
+ read line
+ echo 'Wed Jul 24 05:28:08.020 [FileAllocator] done allocating datafile /tmp/tmp.JrFx5PgGv5/local.ns, size: 16MB,  took 0.002 secs'
+ grep -q 'waiting for connections on port'
+ read line
+ grep -q 'waiting for connections on port'
+ echo 'Wed Jul 24 05:28:08.024 [FileAllocator] allocating new datafile /tmp/tmp.JrFx5PgGv5/local.0, filling with zeroes...'
+ read line
+ echo 'Wed Jul 24 05:28:08.029 [FileAllocator] done allocating datafile /tmp/tmp.JrFx5PgGv5/local.0, size: 16MB,  took 0.004 secs'
+ grep -q 'waiting for connections on port'
+ read line
+ echo 'Wed Jul 24 05:28:08.044 [initandlisten] waiting for connections on port 29000'
+ grep -q 'waiting for connections on port'
+ break
+ cat /tmp/tmp.JrFx5PgGv5/out
+ export CEILOMETER_TEST_MONGODB_URL=mongodb://localhost:29000/ceilometer
+ CEILOMETER_TEST_MONGODB_URL=mongodb://localhost:29000/ceilometer
+ python setup.py testr --slowest '--testr-args=--concurrency=1 tests.storage.test_impl_mongodb.RawSampleTest.test_get_samples_in_default_order'
Wed Jul 24 05:28:08.044 [websvr] admin web console waiting for connections on port 30000
running testr
Wed Jul 24 05:28:13.036 [FileAllocator] allocating new datafile /tmp/tmp.JrFx5PgGv5/ceilometer.ns, filling with zeroes...
Wed Jul 24 05:28:13.039 [FileAllocator] done allocating datafile /tmp/tmp.JrFx5PgGv5/ceilometer.ns, size: 16MB,  took 0.001 secs
Wed Jul 24 05:28:13.039 [FileAllocator] allocating new datafile /tmp/tmp.JrFx5PgGv5/ceilometer.0, filling with zeroes...
Wed Jul 24 05:28:13.044 [FileAllocator] done allocating datafile /tmp/tmp.JrFx5PgGv5/ceilometer.0, size: 16MB,  took 0.004 secs
Wed Jul 24 05:28:13.059 [conn1] build index ceilometer.resource { _id: 1 }
Wed Jul 24 05:28:13.067 [conn1] build index done.  scanned 0 total records. 0.004 secs
Wed Jul 24 05:28:13.068 [conn1] info: creating collection ceilometer.resource on add index
Wed Jul 24 05:28:13.068 [conn1] build index ceilometer.resource { user_id: 1, source: 1 }
Wed Jul 24 05:28:13.072 [conn1] build index done.  scanned 0 total records. 0.004 secs
Wed Jul 24 05:28:13.078 [conn1] build index ceilometer.meter { _id: 1 }
Wed Jul 24 05:28:13.083 [conn1] build index done.  scanned 0 total records. 0.003 secs
Wed Jul 24 05:28:13.083 [conn1] info: creating collection ceilometer.meter on add index
Wed Jul 24 05:28:13.083 [conn1] build index ceilometer.meter { resource_id: 1, user_id: 1, counter_name: 1, timestamp: 1, source: 1 }
Wed Jul 24 05:28:13.089 [conn1] build index done.  scanned 0 total records. 0.005 secs
Wed Jul 24 05:28:13.099 [conn1] dropDatabase ceilometer starting
Wed Jul 24 05:28:13.152 [conn1] removeJournalFiles
Wed Jul 24 05:28:13.161 [conn1] dropDatabase ceilometer finished
Wed Jul 24 05:28:13.163 [FileAllocator] allocating new datafile /tmp/tmp.JrFx5PgGv5/ceilometer.ns, filling with zeroes...
Wed Jul 24 05:28:13.164 [FileAllocator] done allocating datafile /tmp/tmp.JrFx5PgGv5/ceilometer.ns, size: 16MB,  took 0.001 secs
Wed Jul 24 05:28:13.165 [FileAllocator] allocating new datafile /tmp/tmp.JrFx5PgGv5/ceilometer.0, filling with zeroes...
Wed Jul 24 05:28:13.166 [FileAllocator] done allocating datafile /tmp/tmp.JrFx5PgGv5/ceilometer.0, size: 16MB,  took 0 secs
Wed Jul 24 05:28:13.178 [conn1] build index ceilometer.resource { _id: 1 }
Wed Jul 24 05:28:13.182 [conn1] build index done.  scanned 0 total records. 0.003 secs
Wed Jul 24 05:28:13.182 [conn1] info: creating collection ceilometer.resource on add index
Wed Jul 24 05:28:13.182 [conn1] build index ceilometer.resource { user_id: 1, source: 1 }
Wed Jul 24 05:28:13.185 [conn1] build index done.  scanned 0 total records. 0.003 secs
Wed Jul 24 05:28:13.188 [conn1] build index ceilometer.meter { _id: 1 }
Wed Jul 24 05:28:13.193 [conn1] build index done.  scanned 0 total records. 0.004 secs
Wed Jul 24 05:28:13.193 [conn1] info: creating collection ceilometer.meter on add index
Wed Jul 24 05:28:13.193 [conn1] build index ceilometer.meter { resource_id: 1, user_id: 1, counter_name: 1, timestamp: 1, source: 1 }
Wed Jul 24 05:28:13.195 [conn1] build index done.  scanned 0 total records. 0.002 secs
Wed Jul 24 05:28:13.244 [conn1] build index ceilometer.user { _id: 1 }
Wed Jul 24 05:28:13.245 [conn1] build index done.  scanned 0 total records. 0 secs
Wed Jul 24 05:28:13.247 [conn1] build index ceilometer.project { _id: 1 }
Wed Jul 24 05:28:13.248 [conn1] build index done.  scanned 0 total records. 0 secs
Wed Jul 24 05:28:19.734 [conn1] update ceilometer.project query: { _id: "project-id-1355" } update: { $addToSet: { source: "test" } } nscanned:0 idhack:1 nupdated:1 fastmodinsert:1 keyUpdates:0 locks(micros) w:70 176ms
Wed Jul 24 05:28:38.555 [FileAllocator] allocating new datafile /tmp/tmp.JrFx5PgGv5/ceilometer.1, filling with zeroes...
Wed Jul 24 05:28:38.558 [FileAllocator] done allocating datafile /tmp/tmp.JrFx5PgGv5/ceilometer.1, size: 32MB,  took 0.001 secs
Wed Jul 24 05:28:54.743 [conn1] update ceilometer.resource query: { _id: "resource-id-9563" } update: { $set: { source: "test", project_id: "project-id-9563", user_id: "user-id-9563", metadata: { tag: "counter-9563", display_name: "test-server" } }, $addToSet: { meter: { counter_name: "instance", counter_unit: "", counter_type: "cumulative" } } } nscanned:0 nupdated:1 fastmodinsert:1 keyUpdates:0 locks(micros) w:100 149ms
Wed Jul 24 05:29:35.155 [FileAllocator] allocating new datafile /tmp/tmp.JrFx5PgGv5/ceilometer.2, filling with zeroes...
Wed Jul 24 05:29:35.157 [FileAllocator] done allocating datafile /tmp/tmp.JrFx5PgGv5/ceilometer.2, size: 64MB,  took 0.001 secs
Wed Jul 24 05:29:54.912 [conn1] insert ceilometer.meter ninserted:1 keyUpdates:0 locks(micros) w:76 105ms
Wed Jul 24 05:31:25.600 [FileAllocator] allocating new datafile /tmp/tmp.JrFx5PgGv5/ceilometer.3, filling with zeroes...
Wed Jul 24 05:31:25.603 [FileAllocator] done allocating datafile /tmp/tmp.JrFx5PgGv5/ceilometer.3, size: 128MB,  took 0.001 secs
Wed Jul 24 05:31:55.114 [conn1] update ceilometer.project query: { _id: "project-id-52407" } update: { $addToSet: { source: "test" } } nscanned:0 idhack:1 nupdated:1 fastmodinsert:1 keyUpdates:0 locks(micros) w:76 152ms
Wed Jul 24 05:32:25.113 [conn1] update ceilometer.project query: { _id: "project-id-59444" } update: { $addToSet: { source: "test" } } nscanned:0 idhack:1 nupdated:1 fastmodinsert:1 keyUpdates:0 locks(micros) w:71 125ms
Wed Jul 24 05:33:33.357 [conn1] assertion 10128 too much data for sort() with no index.  add an index or specify a smaller limit ns:ceilometer.meter query:{ $query: {}, $orderby: { timestamp: -1 } }
Wed Jul 24 05:33:33.362 [conn1] query ceilometer.meter query: { $query: {}, $orderby: { timestamp: -1 } } ntoreturn:0 keyUpdates:0 exception: too much data for sort() with no index.  add an index or specify a smaller limit code:10128 numYields: 1 locks(micros) r:1315385 reslen:126 883ms
running=${PYTHON:-python} -m subunit.run discover -t ./ ./tests --list 
running=${PYTHON:-python} -m subunit.run discover -t ./ ./tests  --load-list /tmp/tmp5p4EA9
======================================================================
FAIL: tests.storage.test_impl_mongodb.RawSampleTest.test_get_samples_in_default_order
tags: worker-0
----------------------------------------------------------------------
pythonlogging:'': {{{connecting to MongoDB replicaset "" on localhost:29000}}}

Traceback (most recent call last):
  File "/opt/stack/ceilometer/tests/storage/base.py", line 362, in test_get_samples_in_default_order
    for sample in self.conn.get_samples(f):
  File "/opt/stack/ceilometer/ceilometer/storage/impl_mongodb.py", line 577, in get_samples
    for s in samples:
  File "/opt/stack/ceilometer/.tox/py27/local/lib/python2.7/site-packages/pymongo/cursor.py", line 814, in next
    if len(self.__data) or self._refresh():
  File "/opt/stack/ceilometer/.tox/py27/local/lib/python2.7/site-packages/pymongo/cursor.py", line 763, in _refresh
    self.__uuid_subtype))
  File "/opt/stack/ceilometer/.tox/py27/local/lib/python2.7/site-packages/pymongo/cursor.py", line 720, in __send_message
    self.__uuid_subtype)
  File "/opt/stack/ceilometer/.tox/py27/local/lib/python2.7/site-packages/pymongo/helpers.py", line 100, in _unpack_response
    error_object["$err"])
OperationFailure: database error: too much data for sort() with no index.  add an index or specify a smaller limit
======================================================================
FAIL: process-returncode
tags: worker-0
----------------------------------------------------------------------
Binary content:
  traceback (test/plain; charset="utf8")
Ran 3 (+2) tests in 320.696s (+63.827s)
FAILED (id=70, failures=2 (+2))
error: testr failed (1)
+ clean_exit
+ local error_code=1
+ rm -rf /tmp/tmp.JrFx5PgGv5
+ '[' 14029 ']'
+ kill -9 14029
+ return 1
ERROR: InvocationError: '/bin/bash -x /opt/stack/ceilometer/run-tests.sh tests.storage.test_impl_mongodb.RawSampleTest.test_get_samples_in_default_order'
py27 runtests: commands[1] | /opt/stack/ceilometer/tools/conf/check_uptodate.sh
___________________________________ summary ____________________________________
ERROR:   py27: commands failed