[SERVER-5772] assert in query_yield2.js Created: 07/May/12  Updated: 11/Jul/16  Resolved: 12/Jun/12

Status: Closed
Project: Core Server
Component/s: Querying
Affects Version/s: None
Fix Version/s: 2.1.2

Type: Bug Priority: Major - P3
Reporter: Ian Whalen (Inactive) Assignee: Tad Marshall
Resolution: Done Votes: 0
Labels: buildbot
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Windows 64-bit Weekly Slow Tests


Issue Links:
Related
related to SERVER-2659 query_yield2 failure Closed
Operating System: ALL
Participants:

 Description   

Sun May 06 10:20:55 shell: started program mongo.exe --eval TestData = {
	"testPath" : "D:\\10gen\\buildslaves\\mongo\\Windows_64bit_Weekly_Slow_Tests\\mongo\\jstests\\slowWeekly\\query_yield2.js",
	"testFile" : "query_yield2.js",
	"testName" : "query_yield2",
	"noJournal" : false,
	"noJournalPrealloc" : false,
	"auth" : false,
	"keyFile" : null,
	"keyFileData" : null
};jsTest.authenticate(db.getMongo());print( 0 == db.query_yield2.find( function(){ var x=this.n; for ( var i=0; i<50000; i++ ){ x = x * 2; } return false; } ).itcount() );  127.0.0.1:30201
sh3680| MongoDB shell version: 2.1.2-pre-
sh3680| connecting to: 127.0.0.1:30201/test
 m30201| Sun May 06 10:20:55 [initandlisten] connection accepted from 127.0.0.1:49936 #2 (2 connections now open)
start query
assert: [1] != [0] are not equal : nothing in prog
Error("Printing Stack Trace")@:0
()@src/mongo/shell/utils.js:37
("[1] != [0] are not equal : nothing in prog")@src/mongo/shell/utils.js:58
(1,0,"nothing in prog")@src/mongo/shell/utils.js:88
@D:\10gen\buildslaves\mongo\Windows_64bit_Weekly_Slow_Tests\mongo\jstests\slowWeekly\query_yield2.js:63
 
Sun May 06 10:20:55 uncaught exception: [1] != [0] are not equal : nothing in prog
failed to load: D:\10gen\buildslaves\mongo\Windows_64bit_Weekly_Slow_Tests\mongo\jstests\slowWeekly\query_yield2.js

http://buildbot.mongodb.org/builders/Windows%2064-bit%20Weekly%20Slow%20Tests/builds/8/steps/test/logs/stdio



 Comments   
Comment by auto [ 12/Jun/12 ]

Author:

{u'login': u'tadmarshall', u'name': u'Tad Marshall', u'email': u'tad@10gen.com'}

Message: SERVER-5772 wait specifically for our query, not just any currentOp

The test was failing because the wait for currentOp.inprog to become
non-empty was too generous, and would accept "whatsmyuri" (for example)
instead of the query we are trying to wait for. Check for our namespace
and for a "$where" query so we only proceed into the real test after the
parallel query has started.
Branch: master
https://github.com/mongodb/mongo/commit/21d62332b014389af4636ec81b51d7e3a3152081

Comment by Tad Marshall [ 10/Jun/12 ]

Reopening because it happened again. It looks like the test needs to be made defensive against finding a "whatsmyuri" query when it is expecting to see the parallel shell executing the test query.

Comment by Tad Marshall [ 10/Jun/12 ]

Failure happened again, this time in the Linux 64-bit v8 Slow Weekly test run:

http://buildbot.mongodb.org/builders/Linux%2064-bit%20v8%20Weekly%20Slow%20Tests/builds/101/steps/test/logs/stdio

It seems that the "whatsmyuri" query is fooling the test into thinking that the parallel shell has started its query when in fact it has not. The test needs to be made defensive against this.

Sun Jun 10 15:13:20 [initandlisten] MongoDB starting : pid=22063 port=27999 dbpath=/data/db/sconsTests/ 64-bit host=bs-linuxv8
Sun Jun 10 15:13:20 [initandlisten] 
Sun Jun 10 15:13:20 [initandlisten] ** NOTE: This is a development version (2.1.2-pre-) of MongoDB.
Sun Jun 10 15:13:20 [initandlisten] **       Not recommended for production.
Sun Jun 10 15:13:20 [initandlisten] 
Sun Jun 10 15:13:20 [initandlisten] db version v2.1.2-pre-, pdfile version 4.5
Sun Jun 10 15:13:20 [initandlisten] git version: edbdfe32ce35e47b2fd11f7ca413353017f138c1
Sun Jun 10 15:13:20 [initandlisten] build info: Linux bs-linuxv8 2.6.35.14-97.44.amzn1.x86_64 #1 SMP Mon Oct 24 16:03:08 UTC 2011 x86_64 BOOST_LIB_VERSION=1_49
Sun Jun 10 15:13:20 [initandlisten] options: { dbpath: "/data/db/sconsTests/", port: 27999 }
Sun Jun 10 15:13:21 [initandlisten] journal dir=/data/db/sconsTests/journal
Sun Jun 10 15:13:21 [initandlisten] recover : no journal files present, no recovery needed
[Errno 111] Connection refused
[Errno 111] Connection refused
[Errno 111] Connection refused
[Errno 111] Connection refused
Sun Jun 10 15:13:25 [initandlisten] preallocateIsFaster=true 74.92
Sun Jun 10 15:13:25 [initandlisten] preallocateIsFaster check took 4.216 secs
Sun Jun 10 15:13:25 [initandlisten] waiting for connections on port 27999
// ... snip ...
 *******************************************
         Test : query_yield2.js ...
      Command : /data/slave/Linux_64bit_v8_Weekly_Slow_Tests/mongo/mongo --port 27999 --nodb /data/slave/Linux_64bit_v8_Weekly_Slow_Tests/mongo/jstests/slowWeekly/query_yield2.js --eval TestData = new Object();TestData.testPath = "/data/slave/Linux_64bit_v8_Weekly_Slow_Tests/mongo/jstests/slowWeekly/query_yield2.js";TestData.testFile = "query_yield2.js";TestData.testName = "query_yield2";TestData.noJournal = false;TestData.noJournalPrealloc = false;TestData.auth = false;TestData.keyFile = null;TestData.keyFileData = null;
         Date : Sun Jun 10 16:07:20 2012
Sun Jun 10 16:07:20 [conn17] end connection 127.0.0.1:60383 (0 connections now open)
MongoDB shell version: 2.1.2-pre-
null
Sun Jun 10 16:07:21 shell: started program /data/slave/Linux_64bit_v8_Weekly_Slow_Tests/mongo/mongod --port 30201 --dbpath /data/db/query_yield2 --smallfiles --nojournal
 m30201| Sun Jun 10 16:07:21 [initandlisten] MongoDB starting : pid=23912 port=30201 dbpath=/data/db/query_yield2 64-bit host=bs-linuxv8
 m30201| Sun Jun 10 16:07:21 [initandlisten] 
 m30201| Sun Jun 10 16:07:21 [initandlisten] ** NOTE: This is a development version (2.1.2-pre-) of MongoDB.
 m30201| Sun Jun 10 16:07:21 [initandlisten] **       Not recommended for production.
 m30201| Sun Jun 10 16:07:21 [initandlisten] 
 m30201| Sun Jun 10 16:07:21 [initandlisten] db version v2.1.2-pre-, pdfile version 4.5
 m30201| Sun Jun 10 16:07:21 [initandlisten] git version: edbdfe32ce35e47b2fd11f7ca413353017f138c1
 m30201| Sun Jun 10 16:07:21 [initandlisten] build info: Linux bs-linuxv8 2.6.35.14-97.44.amzn1.x86_64 #1 SMP Mon Oct 24 16:03:08 UTC 2011 x86_64 BOOST_LIB_VERSION=1_49
 m30201| Sun Jun 10 16:07:21 [initandlisten] options: { dbpath: "/data/db/query_yield2", nojournal: true, port: 30201, smallfiles: true }
 m30201| Sun Jun 10 16:07:21 [websvr] admin web console waiting for connections on port 31201
 m30201| Sun Jun 10 16:07:21 [initandlisten] waiting for connections on port 30201
 m30201| Sun Jun 10 16:07:21 [initandlisten] connection accepted from 127.0.0.1:38248 #1 (1 connection now open)
 m30201| Sun Jun 10 16:07:21 [conn1] CMD: drop test.query_yield2
Shell ==== Creating test.query_yield2 collection ...
Shell ==== Adding documents until a time-wasting query takes over 2 seconds to complete
Shell ==== Adding document IDs from 0 to 199
 m30201| Sun Jun 10 16:07:21 [FileAllocator] allocating new datafile /data/db/query_yield2/test.ns, filling with zeroes...
 m30201| Sun Jun 10 16:07:21 [FileAllocator] creating directory /data/db/query_yield2/_tmp
 m30201| Sun Jun 10 16:07:21 [FileAllocator] done allocating datafile /data/db/query_yield2/test.ns, size: 16MB,  took 0.001 secs
Shell ==== Running warm-up query 1
 m30201| Sun Jun 10 16:07:21 [FileAllocator] allocating new datafile /data/db/query_yield2/test.0, filling with zeroes...
 m30201| Sun Jun 10 16:07:21 [FileAllocator] done allocating datafile /data/db/query_yield2/test.0, size: 16MB,  took 0.001 secs
 m30201| Sun Jun 10 16:07:21 [FileAllocator] allocating new datafile /data/db/query_yield2/test.1, filling with zeroes...
 m30201| Sun Jun 10 16:07:21 [conn1] build index test.query_yield2 { _id: 1 }
 m30201| Sun Jun 10 16:07:21 [conn1] build index done.  scanned 0 total records. 0 secs
 m30201| Sun Jun 10 16:07:21 [FileAllocator] done allocating datafile /data/db/query_yield2/test.1, size: 32MB,  took 0.001 secs
Shell ==== Running warm-up query 2
Shell ==== Running timed query ...
Shell ==== Query across 200 documents took 17 ms
Shell ==== Did not reach 2000 ms, increasing fill point to 400 documents
Shell ==== Adding document IDs from 200 to 399
Shell ==== Running warm-up query 1
Shell ==== Running warm-up query 2
Shell ==== Running timed query ...
Shell ==== Query across 400 documents took 33 ms
Shell ==== Did not reach 2000 ms, increasing fill point to 800 documents
Shell ==== Adding document IDs from 400 to 799
Shell ==== Running warm-up query 1
Shell ==== Running warm-up query 2
Shell ==== Running timed query ...
Shell ==== Query across 800 documents took 68 ms
Shell ==== Did not reach 2000 ms, increasing fill point to 1600 documents
Shell ==== Adding document IDs from 800 to 1599
Shell ==== Running warm-up query 1
 m30201| Sun Jun 10 16:07:21 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:1600 keyUpdates:0 nreturned:0 reslen:20 137ms
Shell ==== Running warm-up query 2
 m30201| Sun Jun 10 16:07:22 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:1600 keyUpdates:0 nreturned:0 reslen:20 134ms
Shell ==== Running timed query ...
 m30201| Sun Jun 10 16:07:22 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:1600 keyUpdates:0 nreturned:0 reslen:20 146ms
Shell ==== Query across 1600 documents took 147 ms
Shell ==== Did not reach 2000 ms, increasing fill point to 3200 documents
Shell ==== Adding document IDs from 1600 to 3199
Shell ==== Running warm-up query 1
 m30201| Sun Jun 10 16:07:22 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:3200 keyUpdates:0 nreturned:0 reslen:20 273ms
Shell ==== Running warm-up query 2
 m30201| Sun Jun 10 16:07:22 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:3200 keyUpdates:0 nreturned:0 reslen:20 274ms
Shell ==== Running timed query ...
 m30201| Sun Jun 10 16:07:23 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:3200 keyUpdates:0 nreturned:0 reslen:20 281ms
Shell ==== Query across 3200 documents took 282 ms
Shell ==== Did not reach 2000 ms, increasing fill point to 6400 documents
Shell ==== Adding document IDs from 3200 to 6399
Shell ==== Running warm-up query 1
 m30201| Sun Jun 10 16:07:23 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:6400 keyUpdates:0 nreturned:0 reslen:20 549ms
Shell ==== Running warm-up query 2
 m30201| Sun Jun 10 16:07:24 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:6400 keyUpdates:0 nreturned:0 reslen:20 548ms
Shell ==== Running timed query ...
 m30201| Sun Jun 10 16:07:24 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:6400 keyUpdates:0 nreturned:0 reslen:20 544ms
Shell ==== Query across 6400 documents took 545 ms
Shell ==== Did not reach 2000 ms, increasing fill point to 12800 documents
Shell ==== Adding document IDs from 6400 to 12799
Shell ==== Running warm-up query 1
 m30201| Sun Jun 10 16:07:26 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:12800 keyUpdates:0 nreturned:0 reslen:20 1127ms
Shell ==== Running warm-up query 2
 m30201| Sun Jun 10 16:07:27 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:12800 keyUpdates:0 nreturned:0 reslen:20 1055ms
Shell ==== Running timed query ...
 m30201| Sun Jun 10 16:07:28 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:12800 keyUpdates:0 nreturned:0 reslen:20 1073ms
Shell ==== Query across 12800 documents took 1074 ms
Shell ==== Did not reach 2000 ms, increasing fill point to 25600 documents
Shell ==== Adding document IDs from 12800 to 25599
Shell ==== Running warm-up query 1
 m30201| Sun Jun 10 16:07:30 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:25600 keyUpdates:0 nreturned:0 reslen:20 2201ms
Shell ==== Running warm-up query 2
 m30201| Sun Jun 10 16:07:33 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:25600 keyUpdates:0 nreturned:0 reslen:20 2162ms
Shell ==== Running timed query ...
 m30201| Sun Jun 10 16:07:35 [conn1] query test.query_yield2 query: { $where: function () { var x=this.n; for ( var i=0; i<25000; i++ ) { x = x * 2;... } ntoreturn:0 ntoskip:0 nscanned:25600 keyUpdates:0 nreturned:0 reslen:20 2267ms
Shell ==== Query across 25600 documents took 2268 ms
Shell ==== Reached desired 2000 ms mark (at 2268 ms), proceding to next step
Shell ==== Testing db.currentOp to make sure nothing is in progress
Shell ==== Dump of db.currentOp:
{ "inprog" : [ ] }
Shell ==== The test is working so far: db.currentOp().inprog.length is 0
Shell ==== Starting parallel shell to test if slow query will yield to write
Sun Jun 10 16:07:35 shell: started program /data/slave/Linux_64bit_v8_Weekly_Slow_Tests/mongo/mongo --eval TestData = {
	"testPath" : "/data/slave/Linux_64bit_v8_Weekly_Slow_Tests/mongo/jstests/slowWeekly/query_yield2.js",
	"testFile" : "query_yield2.js",
	"testName" : "query_yield2",
	"noJournal" : false,
	"noJournalPrealloc" : false,
	"auth" : false,
	"keyFile" : null,
	"keyFileData" : null
};jsTest.authenticate(db.getMongo());print( 0 == db.query_yield2.find( function(){ var x=this.n; for ( var i=0; i<50000; i++ ){ x = x * 2; } return false; } ).itcount() );  127.0.0.1:30201
Shell ==== Waiting until db.currentOp().inprog becomes non-empty
sh23926| MongoDB shell version: 2.1.2-pre-
 m30201| Sun Jun 10 16:07:35 [initandlisten] connection accepted from 127.0.0.1:38249 #2 (2 connections now open)
Shell ==== Wait satisfied: db.currentOp().inprog.length is 1
Shell ==== Dump of db.currentOp:
{
	"inprog" : [
		{
			"opid" : 25626,
			"active" : false,
			"waitingForLock" : false,
			"op" : "query",
			"ns" : "",
			"query" : {
				"whatsmyuri" : 1
			},
			"client" : "127.0.0.1:38249",
			"desc" : "conn",
			"threadId" : "0x7f03d46f9700",
			"connectionId" : 2,
			"numYields" : 0
		}
	]
}
Shell ==== Now that db.currentOp().inprog is non-empty, we start the real test
Shell ==== Starting loop 0, inserting 1 document
Shell ==== Time to insert document 0 was 1 ms, db.currentOp().inprog.length is 0
Shell ==== TEST FAILED!  db.currentOp().inprog.length is 0
Shell ==== Dump of db.currentOp:
{ "inprog" : [ ] }
Sun Jun 10 16:07:35 exec error: /data/slave/Linux_64bit_v8_Weekly_Slow_Tests/mongo/jstests/slowWeekly/query_yield2.js:99 TEST FAILED!
            throw "TEST FAILED!";
            ^
 
failed to load: /data/slave/Linux_64bit_v8_Weekly_Slow_Tests/mongo/jstests/slowWeekly/query_yield2.js
                15484.485865ms
Sun Jun 10 16:07:36 got signal 15 (Terminated), will terminate after current cmd ends
Sun Jun 10 16:07:36 [interruptThread] now exiting
Sun Jun 10 16:07:36 dbexit: 
Sun Jun 10 16:07:36 [interruptThread] shutdown: going to close listening sockets...
Sun Jun 10 16:07:36 [interruptThread] closing listening socket: 6
Sun Jun 10 16:07:36 [interruptThread] closing listening socket: 7
Sun Jun 10 16:07:36 [interruptThread] closing listening socket: 8
Sun Jun 10 16:07:36 [interruptThread] removing socket file: /tmp/mongodb-27999.sock
Sun Jun 10 16:07:36 [interruptThread] shutdown: going to flush diaglog...
Sun Jun 10 16:07:36 [interruptThread] shutdown: going to close sockets...
Sun Jun 10 16:07:36 [interruptThread] shutdown: waiting for fs preallocator...
Sun Jun 10 16:07:36 [interruptThread] shutdown: lock for final commit...
Sun Jun 10 16:07:36 [interruptThread] shutdown: final commit...
Sun Jun 10 16:07:36 [interruptThread] shutdown: closing all files...
Sun Jun 10 16:07:36 [interruptThread] closeAllFiles() finished
Sun Jun 10 16:07:36 [interruptThread] journalCleanup...
Sun Jun 10 16:07:36 [interruptThread] removeJournalFiles
Sun Jun 10 16:07:36 [interruptThread] shutdown: removing fs lock...
Sun Jun 10 16:07:36 dbexit: really exiting now
test /data/slave/Linux_64bit_v8_Weekly_Slow_Tests/mongo/jstests/slowWeekly/query_yield2.js exited with status 253
16 tests succeeded
3 tests didn't get run
The following tests failed (with exit code):
/data/slave/Linux_64bit_v8_Weekly_Slow_Tests/mongo/jstests/slowWeekly/query_yield2.js	253

Comment by auto [ 03/Jun/12 ]

Author:

{u'login': u'tadmarshall', u'name': u'Tad Marshall', u'email': u'tad@10gen.com'}

Message: SERVER-5772 make query_yield2.js much more verbose

It was impossible to tell what went wrong in this test when
it failed, and it almost always worked. Now, the sequence of
events leading to a failure will be much more obvious.
Branch: master
https://github.com/mongodb/mongo/commit/f0f2d4dab8f5e1cdeff71b58b292bda3d320cc06

Generated at Thu Feb 08 03:09:49 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.