[SERVER-15352] Assertion failure when server gets CTRL+C during MapReduce operation Created: 22/Sep/14  Updated: 26/Sep/14  Resolved: 26/Sep/14

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

Type: Bug Priority: Major - P3
Reporter: Mirek Rusin Assignee: Unassigned
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Steps To Reproduce:

CTRL+C while M/R job is running (& restart?) hoping it'll crash.

Participants:

 Description   

I'm not sure if this should be reported or not, but while M/R job was executing in my dev env on Mac OSX 10.9.5 with MongoDB (2014-09-22T19:20:43.231-0300 git version: nogitversion) I got:

2014-09-22T19:00:48.108-0300 [conn4] 		M/R: (1/3) Emit Progress: 200
^C2014-09-22T19:00:52.091-0300 [signalProcessingThread] got signal 2 (Interrupt: 2), will terminate after current cmd ends
2014-09-22T19:00:52.091-0300 [signalProcessingThread] now exiting
2014-09-22T19:00:52.091-0300 [signalProcessingThread] dbexit: 
2014-09-22T19:00:52.091-0300 [signalProcessingThread] shutdown: going to close listening sockets...
2014-09-22T19:00:52.091-0300 [signalProcessingThread] closing listening socket: 7
2014-09-22T19:00:52.091-0300 [signalProcessingThread] closing listening socket: 9
2014-09-22T19:00:52.091-0300 [signalProcessingThread] removing socket file: /tmp/mongodb-27017.sock
2014-09-22T19:00:52.091-0300 [signalProcessingThread] shutdown: going to flush diaglog...
2014-09-22T19:00:52.091-0300 [signalProcessingThread] shutdown: going to close sockets...
2014-09-22T19:00:52.091-0300 [signalProcessingThread] shutdown: waiting for fs preallocator...
2014-09-22T19:00:52.091-0300 [signalProcessingThread] shutdown: lock for final commit...
2014-09-22T19:00:52.091-0300 [signalProcessingThread] shutdown: final commit...
2014-09-22T19:00:52.092-0300 [conn4] Assertion: 16496:V8: NULL Object template instantiated. v8 still executing.
2014-09-22T19:00:52.110-0300 [conn4] core-development.profiles 0x103e4631a 0x103dfbe44 0x103deb77c 0x103deb5ea 0x103dd2862 0x103dd022b 0x103dd03bb 0x103dd5eac 0x103dc9776 0x103885683 0x10387a613 0x103879dd0 0x1038847bc 0x10388515e 0x10388a436 0x1038e6a89 0x1038e7ae9 0x1038e8f51 0x103b264fc 0x1039d5f0b 
 0   mongod                              0x0000000103e4631a _ZN5mongo15printStackTraceERNSt3__113basic_ostreamIcNS0_11char_traitsIcEEEE + 58
 1   mongod                              0x0000000103dfbe44 _ZN5mongo10logContextEPKc + 196
 2   mongod                              0x0000000103deb77c _ZN5mongo11msgassertedEiPKc + 396
 3   mongod                              0x0000000103deb5ea _ZN5mongo11msgassertedEiRKNSt3__112basic_stringIcNS0_11char_traitsIcEENS0_9allocatorIcEEEE + 26
 4   mongod                              0x0000000103dd2862 _ZN5mongo7V8Scope11mongoToLZV8ERKNS_7BSONObjEb + 1250
 5   mongod                              0x0000000103dd022b _ZN5mongo7V8Scope16mongoToV8ElementERKNS_11BSONElementEb + 411
 6   mongod                              0x0000000103dd03bb _ZN5mongo7V8Scope16mongoToV8ElementERKNS_11BSONElementEb + 811
 7   mongod                              0x0000000103dd5eac _ZN5mongo7V8Scope6invokeEyPKNS_7BSONObjES3_ibbb + 780
 8   mongod                              0x0000000103dc9776 _ZN5mongo11PooledScope6invokeEyPKNS_7BSONObjES3_ibbb + 54
 9   mongod                              0x0000000103885683 _ZN5mongo5Scope10invokeSafeEyPKNS_7BSONObjES3_ibbb + 51
 10  mongod                              0x000000010387a613 _ZN5mongo2mr9JSReducer7_reduceERKNSt3__16vectorINS_7BSONObjENS2_9allocatorIS4_EEEERS4_Ri + 1715
 11  mongod                              0x0000000103879dd0 _ZN5mongo2mr9JSReducer6reduceERKNSt3__16vectorINS_7BSONObjENS2_9allocatorIS4_EEEE + 128
 12  mongod                              0x00000001038847bc _ZN5mongo2mr5State14reduceInMemoryEv + 268
 13  mongod                              0x000000010388515e _ZN5mongo2mr5State35reduceAndSpillInMemoryStateIfNeededEv + 990
 14  mongod                              0x000000010388a436 _ZN5mongo2mr16MapReduceCommand3runERKNSt3__112basic_stringIcNS2_11char_traitsIcEENS2_9allocatorIcEEEERNS_7BSONObjEiRS8_RNS_14BSONObjBuilderEb + 2278
 15  mongod                              0x00000001038e6a89 _ZN5mongo12_execCommandEPNS_7CommandERKNSt3__112basic_stringIcNS2_11char_traitsIcEENS2_9allocatorIcEEEERNS_7BSONObjEiRS8_RNS_14BSONObjBuilderEb + 41
 16  mongod                              0x00000001038e7ae9 _ZN5mongo7Command11execCommandEPS0_RNS_6ClientEiPKcRNS_7BSONObjERNS_14BSONObjBuilderEb + 2921
 17  mongod                              0x00000001038e8f51 _ZN5mongo12_runCommandsEPKcRNS_7BSONObjERNS_11_BufBuilderINS_16TrivialAllocatorEEERNS_14BSONObjBuilderEbi + 1313
 18  mongod                              0x0000000103b264fc _ZN5mongo11newRunQueryERNS_7MessageERNS_12QueryMessageERNS_5CurOpES1_ + 876
 19  mongod                              0x00000001039d5f0b _ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE + 2347
2014-09-22T19:00:52.147-0300 [signalProcessingThread] shutdown: closing all files...
2014-09-22T19:00:52.233-0300 [signalProcessingThread] closeAllFiles() finished
2014-09-22T19:00:52.233-0300 [signalProcessingThread] journalCleanup...
2014-09-22T19:00:52.233-0300 [signalProcessingThread] removeJournalFiles
2014-09-22T19:00:52.233-0300 [signalProcessingThread] shutdown: removing fs lock...
2014-09-22T19:00:52.233-0300 [signalProcessingThread] dbexit: really exiting now



 Comments   
Comment by Ramon Fernandez Marina [ 26/Sep/14 ]

Hi mirek,

what you're seeing is not a crash, but an assertion failure. I tried to reproduce with a million documents with this shape:

{ "_id" : ObjectId("5425a8fe84def9daf1371ef0"), "x" : <number between 1 and 100> }

and a very simple mapreduce:

var map1 = function() { emit(this._id, this.x); };
var red1 = function(id, x) { x };
db.foo.mapReduce( map1, red1, { out: {merge: "out" }});

This is what I see in my logs:

2014-09-26T14:08:37.015-0400 [conn7] 		M/R: (1/3) Emit Progress: 130200/1000000	13%
2014-09-26T14:08:40.000-0400 [conn7] 		M/R: (1/3) Emit Progress: 270200/1000000	27%
2014-09-26T14:08:41.127-0400 [signalProcessingThread] got signal 2 (Interrupt: 2), will terminate after current cmd ends
2014-09-26T14:08:41.127-0400 [conn7] JavaScript execution terminated
2014-09-26T14:08:41.128-0400 [signalProcessingThread] now exiting
2014-09-26T14:08:41.128-0400 [conn7] mr failed, removing collection :: caused by :: 16712 JavaScript execution terminated
2014-09-26T14:08:41.128-0400 [signalProcessingThread] dbexit: 
2014-09-26T14:08:41.129-0400 [signalProcessingThread] shutdown: going to close listening sockets...
2014-09-26T14:08:41.129-0400 [signalProcessingThread] closing listening socket: 9
2014-09-26T14:08:41.129-0400 [signalProcessingThread] closing listening socket: 10
2014-09-26T14:08:41.129-0400 [signalProcessingThread] removing socket file: /tmp/mongodb-27017.sock
2014-09-26T14:08:41.130-0400 [signalProcessingThread] shutdown: going to flush diaglog...
2014-09-26T14:08:41.130-0400 [signalProcessingThread] shutdown: going to close sockets...
2014-09-26T14:08:41.130-0400 [signalProcessingThread] shutdown: waiting for fs preallocator...
2014-09-26T14:08:41.130-0400 [signalProcessingThread] shutdown: lock for final commit...
2014-09-26T14:08:41.131-0400 [signalProcessingThread] shutdown: final commit...
2014-09-26T14:08:41.139-0400 [conn7] command test.$cmd command: mapReduce { mapreduce: "foo", map: function () { emit(this._id, this.x); }, reduce: function (id, x) { x }, out: { merge: "out" } } planSummary: COLLSCAN keyUpdates:0 numYields:3230 locks(micros) r:8082257 w:1789175 reslen:102 6971ms
2014-09-26T14:08:41.140-0400 [conn7] SocketException handling request, closing client connection: 9001 socket exception [SEND_ERROR] server [127.0.0.1:65339] 
2014-09-26T14:08:41.230-0400 [signalProcessingThread] shutdown: closing all files...
2014-09-26T14:08:41.240-0400 [signalProcessingThread] closeAllFiles() finished
2014-09-26T14:08:41.240-0400 [signalProcessingThread] journalCleanup...
2014-09-26T14:08:41.240-0400 [signalProcessingThread] removeJournalFiles
2014-09-26T14:08:41.243-0400 [signalProcessingThread] shutdown: removing fs lock...
2014-09-26T14:08:41.243-0400 [signalProcessingThread] dbexit: really exiting now

I'd say this works as designed: the shell is still running some operations while the server is shutting down (hence the v8 still executing line in your logs). The rest of your logs show a clean shutdown of the server.

I'm thus going to resolve this ticket. However, if you're able to reproduce this reliably and can upload your scripts and dataset please reopen the ticket so we can investigate if there's an issue lurking somewhere.

Regards,
Ramón.

Comment by Mirek Rusin [ 22/Sep/14 ]

$ mongo
MongoDB shell version: 2.6.4
connecting to: test
Server has startup warnings:
2014-09-22T19:17:12.564-0300 [initandlisten]
2014-09-22T19:17:12.564-0300 [initandlisten] ** WARNING: soft rlimits too low. Number of files is 256, should be at least 1000
> db.serverBuildInfo()
{
"version" : "2.6.4",
"gitVersion" : "nogitversion",
"OpenSSLVersion" : "",
"sysInfo" : "Darwin minimavericks.local 13.3.0 Darwin Kernel Version 13.3.0: Tue Jun 3 21:27:35 PDT 2014; root:xnu-2422.110.17~1/RELEASE_X86_64 x86_64 BOOST_LIB_VERSION=1_49",
"loaderFlags" : "-fPIC -pthread -Wl,-bind_at_load -m64 -mmacosx-version-min=10.9",
"compilerFlags" : "-Wnon-virtual-dtor -Woverloaded-virtual -fPIC -fno-strict-aliasing -ggdb -pthread -Wall -Wsign-compare -Wno-unknown-pragmas -Winvalid-pch -pipe -Werror -O3 -m64 -Wno-unused-function -Wno-unused-private-field -Wno-deprecated-declarations -Wno-tautological-constant-out-of-range-compare -Wno-unused-const-variable -mmacosx-version-min=10.9",
"allocator" : "tcmalloc",
"versionArray" : [
2,
6,
4,
0
],
"javascriptEngine" : "V8",
"bits" : 64,
"debug" : false,
"maxBsonObjectSize" : 16777216,
"ok" : 1
}

Comment by Ramon Fernandez Marina [ 22/Sep/14 ]

Can you please post the output of running db.serverBuildInfo() in the shell?

Comment by Mirek Rusin [ 22/Sep/14 ]

I'm not sure if it crashed when exiting or when I restarted it quickly just after exiting. I believe it crashed during restart immediatelly after closing with CTRL+C.

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