-
Type: Bug
-
Resolution: Done
-
Priority: Major - P3
-
Affects Version/s: None
-
Component/s: Testing Infrastructure
-
Environment:Windows 64-bit debug buildslave running nightly tests
-
Windows
Test : geo_s2near.js ... Command : D:\slave\Windows_64bit_DEBUG_Nightly\mongo\mongo.exe --port 27999 D:\slave\Windows_64bit_DEBUG_Nightly\mongo\jstests\geo_s2near.js --eval TestData = new Object();TestData.testPath = "D:\\slave\\Windows_64bit_DEBUG_Nightly\\mongo\\jstests\\geo_s2near.js";TestData.testFile = "geo_s2near.js";TestData.testName = "geo_s2near";TestData.noJournal = false;TestData.noJournalPrealloc = false;TestData.auth = false;TestData.keyFile = null;TestData.keyFileData = null; Date : Sun Dec 9 03:38:29 2012 (output suppressed; see http://buildlogs.mongodb.org/build/50c43a78d2a60f526a000afd/test/50c44e06d2a60f3bc0000344/) command timed out: 10800 seconds without output, attempting to kill program finished with exit code 1 elapsedTime=14338.777000
http://buildlogs.mongodb.org/Nightly%20Windows%2064-bit%20DEBUG/builds/151/test/js/geo_s2near.js
Sun Dec 09 03:38:29.378 [conn30] CMD: drop test.geo_s2indexoldformat Sun Dec 09 03:38:29.393 [conn30] build index test.geo_s2indexoldformat { _id: 1 } Sun Dec 09 03:38:29.409 [conn30] build index done. scanned 0 total records. 0.002 secs Sun Dec 09 03:38:29.440 [conn30] build index test.geo_s2indexoldformat { geo: "2dsphere", nonGeo: 1.0 } Sun Dec 09 03:38:29.518 [conn30] build index done. scanned 7 total records. 0.078 secs Sun Dec 09 03:38:29.627 [conn30] end connection 127.0.0.1:60338 (0 connections now open) Sun Dec 09 03:38:29.768 [initandlisten] connection accepted from 127.0.0.1:60345 #31 (1 connection now open) Sun Dec 09 03:38:29.768 [conn31] end connection 127.0.0.1:60345 (0 connections now open) Sun Dec 09 03:38:31.203 [initandlisten] connection accepted from 127.0.0.1:60352 #32 (1 connection now open) Sun Dec 09 03:38:31.265 [conn32] CMD: drop test.geo_s2near Sun Dec 09 03:38:31.297 [conn32] build index test.geo_s2near { _id: 1 } Sun Dec 09 03:38:31.297 [conn32] build index done. scanned 0 total records. 0.002 secs Sun Dec 09 03:38:32.357 [conn32] build index test.geo_s2near { geo: "2dsphere" } Sun Dec 09 03:38:32.451 [conn32] build index done. scanned 400 total records. 0.096 secs Sun Dec 09 03:38:32.654 [conn32] query test.geo_s2near query: { geo: { $near: { $geometry: { type: "Point", coordinates: [ 0.0, 0.0 ] }, $maxDistance: 2000.0 } } } cursorid:568662404306888 ntoreturn:10 ntoskip:0 keyUpdates:0 locks(micros) r:107416 nreturned:10 reslen:900 107ms Sun Dec 09 03:38:32.888 [conn32] query test.geo_s2near query: { geo: { $near: { $geometry: { type: "Point", coordinates: [ 0.0, 0.0 ] } } } } cursorid:569306527266533 ntoreturn:10 ntoskip:0 keyUpdates:0 locks(micros) r:127163 nreturned:10 reslen:900 127ms Sun Dec 09 03:38:49.814 [conn32] Trying to create BSON indexing obj w/too many regions = 9172 Sun Dec 09 03:38:49.814 [conn32] Modifying coverer from (7,17) to (5,7) Sun Dec 09 03:38:49.814 [conn32] New #regions = 636 Sun Dec 09 03:38:55.461 [conn32] Trying to create BSON indexing obj w/too many regions = 32224 Sun Dec 09 03:38:55.461 [conn32] Modifying coverer from (7,17) to (5,7) Sun Dec 09 03:38:55.461 [conn32] New #regions = 2116 Sun Dec 09 03:39:16.630 [conn32] Trying to create BSON indexing obj w/too many regions = 54036
Trying to reproduce this locally:
12:39:12.43 G:\Visual Studio 2010 Projects\mongodev> buildscripts\smoke.py jstests\geo_s2near.js cwd [G:\Visual Studio 2010 Projects\mongodev] removing: /data/db/sconsTests/journal/j._0 removing: /data/db/sconsTests//mongod.lock removing: /data/db/sconsTests//test.0 removing: /data/db/sconsTests//test.1 removing: /data/db/sconsTests//test.ns running G:\Visual Studio 2010 Projects\mongodev\mongod.exe --port 27999 --dbpath /data/db/sconsTests/ Sun Dec 09 12:39:41.462 [initandlisten] MongoDB starting : pid=5396 port=27999 dbpath=/data/db/sconsTests 64-bit host=MissLucy Sun Dec 09 12:39:41.463 [initandlisten] _DEBUG build (which is slower) Sun Dec 09 12:39:41.463 [initandlisten] Sun Dec 09 12:39:41.464 [initandlisten] ** NOTE: This is a development version (2.3.2-pre-) of MongoDB. Sun Dec 09 12:39:41.465 [initandlisten] ** Not recommended for production. Sun Dec 09 12:39:41.466 [initandlisten] Sun Dec 09 12:39:41.467 [initandlisten] db version v2.3.2-pre-, pdfile version 4.5 Sun Dec 09 12:39:41.467 [initandlisten] git version: be0a3384012985ed2f8b0b568b93628bcb0c2ec8 Sun Dec 09 12:39:41.468 [initandlisten] build info: windows sys.getwindowsversion(major=6, minor=1, build=7601, platform=2, service_pack='Service Pack 1') BOOST_LIB_VERSION=1_49 Sun Dec 09 12:39:41.469 [initandlisten] options: { dbpath: "/data/db/sconsTests/", port: 27999 } Sun Dec 09 12:39:41.477 [initandlisten] journal dir=/data/db/sconsTests\journal Sun Dec 09 12:39:41.477 [initandlisten] recover : no journal files present, no recovery needed Sun Dec 09 12:39:41.487 [initandlisten] opening db: local Sun Dec 09 12:39:41.507 [initandlisten] waiting for connections on port 27999 Sun Dec 09 12:39:41.507 [websvr] admin web console waiting for connections on port 28999 Sun Dec 09 12:39:41.508 [IndexRebuilder] thread IndexRebuilder stack usage was 6048 bytes, which is the most so far ******************************************* Sun Dec 09 12:39:42.366 [initandlisten] connection accepted from 127.0.0.1:56191 #1 (1 connection now open) Test : geo_s2near.js ... Sun Dec 09 12:39:42.367 [conn1] end connection 127.0.0.1:56191 (0 connections now open) Sun Dec 09 12:39:42.369 [conn1] thread conn1 stack usage was 13168 bytes, which is the most so far Command : G:\Visual Studio 2010 Projects\mongodev\mongo.exe --port 27999 G:\Visual Studio 2010 Projects\mongodev\jstests\geo_s2near.js --eval TestData = new Object();TestData.testPath = "G:\\Visual Studio 2010 Projects\\mongodev\\jstests\\geo_s2near.js";TestData.testFile = "geo_s2near.js";TestData.testName = "geo_s2near";TestData.noJournal = false;TestData.noJournalPrealloc = false;TestData.auth = false;TestData.keyFile = null;TestData.keyFileData = null; Date : Sun Dec 9 12:39:42 2012 MongoDB shell version: 2.3.2-pre- connecting to: 127.0.0.1:27999/test Sun Dec 09 12:39:42.989 [initandlisten] connection accepted from 127.0.0.1:56192 #2 (1 connection now open) null Sun Dec 09 12:39:43.015 [conn2] opening db: test Sun Dec 09 12:39:43.015 [conn2] CMD: drop test.geo_s2near Sun Dec 09 12:39:43.029 [FileAllocator] allocating new datafile /data/db/sconsTests\test.ns, filling with zeroes... Sun Dec 09 12:39:43.029 [FileAllocator] creating directory /data/db/sconsTests\_tmp Sun Dec 09 12:39:43.107 [FileAllocator] done allocating datafile /data/db/sconsTests\test.ns, size: 16MB, took 0.077 secs Sun Dec 09 12:39:43.108 [FileAllocator] allocating new datafile /data/db/sconsTests\test.0, filling with zeroes... Sun Dec 09 12:39:43.418 [FileAllocator] done allocating datafile /data/db/sconsTests\test.0, size: 64MB, took 0.309 secs Sun Dec 09 12:39:43.419 [conn2] datafileheader::init initializing /data/db/sconsTests\test.0 n:0 Sun Dec 09 12:39:43.419 [FileAllocator] allocating new datafile /data/db/sconsTests\test.1, filling with zeroes... Sun Dec 09 12:39:43.421 [conn2] build index test.geo_s2near { _id: 1 } Sun Dec 09 12:39:43.422 [conn2] build index done. scanned 0 total records. 0.001 secs Sun Dec 09 12:39:43.423 [conn2] insert test.geo_s2near keyUpdates:0 locks(micros) w:394052 394ms Sun Dec 09 12:39:43.818 [conn2] build index test.geo_s2near { geo: "2dsphere" } Sun Dec 09 12:39:43.875 [conn2] build index done. scanned 400 total records. 0.056 secs Sun Dec 09 12:39:44.038 [FileAllocator] done allocating datafile /data/db/sconsTests\test.1, size: 128MB, took 0.617 secs Sun Dec 09 12:39:53.828 [conn2] Trying to create BSON indexing obj w/too many regions = 9172 Sun Dec 09 12:39:53.828 [conn2] Modifying coverer from (7,17) to (5,7) Sun Dec 09 12:39:53.828 [conn2] New #regions = 636 Sun Dec 09 12:39:57.065 [conn2] Trying to create BSON indexing obj w/too many regions = 32224 Sun Dec 09 12:39:57.065 [conn2] Modifying coverer from (7,17) to (5,7) Sun Dec 09 12:39:57.065 [conn2] New #regions = 2116 Sun Dec 09 12:40:09.102 [conn2] Trying to create BSON indexing obj w/too many regions = 54036 Sun Dec 09 12:40:09.103 [conn2] Modifying coverer from (7,17) to (5,7) Sun Dec 09 12:40:09.103 [conn2] New #regions = 3436 Sun Dec 09 12:40:31.638 [conn2] *** unhandled exception 0x80000003 at 0x0000000140ED2639, terminating Sun Dec 09 12:40:31.638 [conn2] *** stack trace for unhandled exception: Sun Dec 09 12:40:31.989 [conn2] mongod.exe f:\dd\vctools\crt_bld\self_64_amd64\crt\src\stdthrow.cpp(15) std::_Debug_message+0x39 Sun Dec 09 12:40:31.989 [conn2] mongod.exe g:\program files (x86)\microsoft visual studio 10.0\vc\include\vector(71) std::_Vector_const_iterator<std::_Vector_val<mongo::S2NearCu rsor::Result,std::allocator<mongo::S2NearCursor::Result> > >::operator*+0x88 Sun Dec 09 12:40:31.990 [conn2] mongod.exe g:\program files (x86)\microsoft visual studio 10.0\vc\include\vector(323) std::_Vector_iterator<std::_Vector_val<mongo::S2NearCursor:: Result,std::allocator<mongo::S2NearCursor::Result> > >::operator*+0x28 Sun Dec 09 12:40:31.991 [conn2] mongod.exe g:\program files (x86)\microsoft visual studio 10.0\vc\include\vector(957) std::vector<mongo::S2NearCursor::Result,std::allocator<mongo ::S2NearCursor::Result> >::front+0x4f Sun Dec 09 12:40:31.993 [conn2] mongod.exe g:\program files (x86)\microsoft visual studio 10.0\vc\include\queue(338) std::priority_queue<mongo::S2NearCursor::Result,std::vector< mongo::S2NearCursor::Result,std::allocator<mongo::S2NearCursor::Result> >,std::less<mongo::S2NearCursor::Result> >::top+0x28 Sun Dec 09 12:40:31.995 [conn2] mongod.exe ...\src\mongo\db\geo\s2nearcursor.cpp(67) mongo::S2NearCursor::current+0x3e Sun Dec 09 12:40:31.996 [conn2] mongod.exe ...\src\mongo\db\geo\s2index.cpp(437) mongo::run2DSphereGeoNear+0x9ee Sun Dec 09 12:40:32.003 [conn2] mongod.exe ...\src\mongo\db\geo\geonear.cpp(70) mongo::Geo2dFindNearCmd::run+0x395 Sun Dec 09 12:40:32.004 [conn2] mongod.exe ...\src\mongo\db\dbcommands.cpp(1862) mongo::_execCommand+0xbf Sun Dec 09 12:40:32.005 [conn2] mongod.exe ...\src\mongo\db\dbcommands.cpp(2012) mongo::execCommand+0xfb4 Sun Dec 09 12:40:32.006 [conn2] mongod.exe ...\src\mongo\db\dbcommands.cpp(2090) mongo::_runCommands+0x3e9 Sun Dec 09 12:40:32.006 [conn2] mongod.exe ...\src\mongo\db\ops\query.cpp(43) mongo::runCommands+0x7b Sun Dec 09 12:40:32.007 [conn2] mongod.exe ...\src\mongo\db\ops\query.cpp(945) mongo::runQuery+0x477 Sun Dec 09 12:40:32.008 [conn2] mongod.exe ...\src\mongo\db\instance.cpp(260) mongo::receivedQuery+0x2f0 Sun Dec 09 12:40:32.009 [conn2] mongod.exe ...\src\mongo\db\instance.cpp(406) mongo::assembleResponse+0x36e Sun Dec 09 12:40:32.009 [conn2] mongod.exe ...\src\mongo\db\db.cpp(196) mongo::MyMessageHandler::process+0x133 Sun Dec 09 12:40:32.010 [conn2] mongod.exe ...\src\mongo\util\net\message_server_port.cpp(206) mongo::PortMessageServer::handleIncomingMsg+0x676 Sun Dec 09 12:40:32.011 [conn2] mongod.exe ...\src\third_party\boost\boost\bind\bind.hpp(244) boost::_bi::list1<boost::_bi::value<mongo::PortMessageServer ::HandleIncomingMsgParam * __ptr64> >::operator()<void * __ptr64,void * __ptr64 (__cdecl*)(void * __ptr64),boost::_bi::list0>+0x56 Sun Dec 09 12:40:32.012 [conn2] mongod.exe ...\src\third_party\boost\boost\bind\bind_template.hpp(21) boost::_bi::bind_t<void * __ptr64,void * __ptr64 (__cdecl*)( void * __ptr64),boost::_bi::list1<boost::_bi::value<mongo::PortMessageServer::HandleIncomingMsgParam * __ptr64> > >::operator()+0x61 Sun Dec 09 12:40:32.012 [conn2] mongod.exe ...\src\third_party\boost\boost\thread\detail\thread.hpp(63) boost::detail::thread_data<boost::_bi::bind_t<void * __ptr64 ,void * __ptr64 (__cdecl*)(void * __ptr64),boost::_bi::list1<boost::_bi::value<mongo::PortMessageServer::HandleIncomingMsgParam * __ptr64> > > >::run+0x2f Sun Dec 09 12:40:32.014 [conn2] writing minidump diagnostic file mongo.dmp Sun Dec 09 12:40:32.033 [conn2] *** immediate exit due to unhandled exception Sun Dec 09 12:40:32.035 Socket recv() errno:10054 An existing connection was forcibly closed by the remote host. 127.0.0.1:27999 Sun Dec 09 12:40:32.035 SocketException: remote: 127.0.0.1:27999 error: 9001 socket exception [1] server [127.0.0.1:27999] Sun Dec 09 12:40:32.040 DBClientCursor::init call() failed Sun Dec 09 12:40:32.052 exec error: src/mongo/shell/query.js:78 error doing query: failed this._cursor = this._mongo.find( this._ns , this._query , this._fields , this. ^ failed to load: G:\Visual Studio 2010 Projects\mongodev\jstests\geo_s2near.js 49692.000151ms test G:\Visual Studio 2010 Projects\mongodev\jstests\geo_s2near.js exited with status -3 0 tests succeeded The following tests failed (with exit code): G:\Visual Studio 2010 Projects\mongodev\jstests\geo_s2near.js -3 Traceback (most recent call last): File "G:\Visual Studio 2010 Projects\mongodev\buildscripts\smoke.py", line 928, in <module> main() File "G:\Visual Studio 2010 Projects\mongodev\buildscripts\smoke.py", line 924, in main report() File "G:\Visual Studio 2010 Projects\mongodev\buildscripts\smoke.py", line 589, in report raise Exception("Test failures") Exception: Test failures
The "unhandled exception" is a breakpoint exception caused by a breakpoint in the debug C runtime. The dialog that pops up (and can't be seen in the AWS log, but is the reason that the test was killed after 3 hours [10800 seconds]) says "vector iterator not dereferencable".
Breaking into the debugger when the breakpoint is hit shows this stack trace:
>Debug.ListCallStack Index Function -------------------------------------------------------------------------------- 1 mongod.exe!std::_Debug_message(const wchar_t * message=0x0000000140a15e30, const wchar_t * file=0x0000000140a0f2b0, unsigned int line=0x00000046) 2 mongod.exe!std::_Vector_const_iterator<std::_Vector_val<mongo::S2NearCursor::Result,std::allocator<mongo::S2NearCursor::Result> > >::operator*() 3 mongod.exe!std::_Vector_iterator<std::_Vector_val<mongo::S2NearCursor::Result,std::allocator<mongo::S2NearCursor::Result> > >::operator*() 4 mongod.exe!std::vector<mongo::S2NearCursor::Result,std::allocator<mongo::S2NearCursor::Result> >::front() 5 mongod.exe!std::priority_queue<mongo::S2NearCursor::Result,std::vector<mongo::S2NearCursor::Result,std::allocator<mongo::S2NearCursor::Result> >,std::less<mongo::S2NearCursor::Result> >::top() 6 mongod.exe!mongo::S2NearCursor::current() 7 mongod.exe!mongo::run2DSphereGeoNear(const mongo::IndexDetails & id={...}, mongo::BSONObj & cmdObj={...}, std::basic_string<char,std::char_traits<char>,std::allocator<char> > & errmsg="", mongo::BSONObjBuilder & result={...}) 8 mongod.exe!mongo::Geo2dFindNearCmd::run(const std::basic_string<char,std::char_traits<char>,std::allocator<char> > & dbname="test", mongo::BSONObj & cmdObj={...}, int __formal=0x00000000, std::basic_string<char,std::char_traits<char>,std::allocator<char> > & errmsg="", mongo::BSONObjBuilder & result={...}, bool fromRepl=false) *9 mongod.exe!mongo::_execCommand(mongo::Command * c=0x000000014139bd70, const std::basic_string<char,std::char_traits<char>,std::allocator<char> > & dbname="test", mongo::BSONObj & cmdObj={...}, int queryOptions=0x00000000, mongo::BSONObjBuilder & result={...}, bool fromRepl=false) 10 mongod.exe!mongo::execCommand(mongo::Command * c=0x000000014139bd70, mongo::Client & client={...}, int queryOptions=0x00000000, const char * cmdns=0x00000000039d7ca4, mongo::BSONObj & cmdObj={...}, mongo::BSONObjBuilder & result={...}, bool fromRepl=false) 11 mongod.exe!mongo::_runCommands(const char * ns=0x00000000039d7ca4, mongo::BSONObj & _cmdobj={...}, mongo::_BufBuilder<mongo::TrivialAllocator> & b={...}, mongo::BSONObjBuilder & anObjBuilder={...}, bool fromRepl=false, int queryOptions=0x00000000) 12 mongod.exe!mongo::runCommands(const char * ns=0x00000000039d7ca4, mongo::BSONObj & jsobj={...}, mongo::CurOp & curop={...}, mongo::_BufBuilder<mongo::TrivialAllocator> & b={...}, mongo::BSONObjBuilder & anObjBuilder={...}, bool fromRepl=false, int queryOptions=0x00000000) 13 mongod.exe!mongo::runQuery(mongo::Message & m={...}, mongo::QueryMessage & q={...}, mongo::CurOp & curop={...}, mongo::Message & result={...}) 14 mongod.exe!mongo::receivedQuery(mongo::Client & c={...}, mongo::DbResponse & dbresponse={...}, mongo::Message & m={...}) 15 mongod.exe!mongo::assembleResponse(mongo::Message & m={...}, mongo::DbResponse & dbresponse={...}, const mongo::HostAndPort & remote={...}) 16 mongod.exe!mongo::MyMessageHandler::process(mongo::Message & m={...}, mongo::AbstractMessagingPort * port=0x0000000003931560, mongo::LastError * le=0x00000000039311f0) 17 mongod.exe!mongo::PortMessageServer::handleIncomingMsg(void * arg=0x000000000392ab10) 18 mongod.exe!boost::_bi::list1<boost::_bi::value<mongo::PortMessageServer::HandleIncomingMsgParam * __ptr64> >::operator()<void * __ptr64,void * __ptr64 (__cdecl*)(void * __ptr64),boost::_bi::list0>(boost::_bi::type<void *> __formal={...}, void * (void *)* & f=0x000000013f441b6f, boost::_bi::list0 & a={...}, boost::_bi::type<void *> __formal={...}) 19 mongod.exe!boost::_bi::bind_t<void * __ptr64,void * __ptr64 (__cdecl*)(void * __ptr64),boost::_bi::list1<boost::_bi::value<mongo::PortMessageServer::HandleIncomingMsgParam * __ptr64> > >::operator()() 20 mongod.exe!boost::detail::thread_data<boost::_bi::bind_t<void * __ptr64,void * __ptr64 (__cdecl*)(void * __ptr64),boost::_bi::list1<boost::_bi::value<mongo::PortMessageServer::HandleIncomingMsgParam * __ptr64> > > >::run() 21 mongod.exe!boost::`anonymous namespace'::thread_start_function(void * param=0x00000000002d2be0) 22 mongod.exe!_callthreadstartex() 23 mongod.exe!_threadstartex(void * ptd=0x0000000003973f50) 24 kernel32.dll!BaseThreadInitThunk() 25 ntdll.dll!RtlUserThreadStart() >
This is the code that triggered the breakpoint call:
reference operator*() const { // return designated object #if _ITERATOR_DEBUG_LEVEL == 2 if (this->_Getcont() == 0 || this->_Ptr == 0 || this->_Ptr < ((_Myvec *)this->_Getcont())->_Myfirst || ((_Myvec *)this->_Getcont())->_Mylast <= this->_Ptr) { // report error _DEBUG_ERROR("vector iterator not dereferencable"); _SCL_SECURE_OUT_OF_RANGE; } #elif _ITERATOR_DEBUG_LEVEL == 1 _SCL_SECURE_VALIDATE(this->_Getcont() != 0); _SCL_SECURE_VALIDATE_RANGE( this->_Ptr != 0 && ((_Myvec *)this->_Getcont())->_Myfirst <= this->_Ptr && this->_Ptr < ((_Myvec *)this->_Getcont())->_Mylast); #endif /* _ITERATOR_DEBUG_LEVEL */ __analysis_assume(this->_Ptr != 0); return (*this->_Ptr); }