[SERVER-11762] ProgressMeter is not thread-safe Created: 18/Nov/13  Updated: 13/Oct/21  Resolved: 02/Dec/13

Status: Closed
Project: Core Server
Component/s: Admin, Stability
Affects Version/s: 2.5.4
Fix Version/s: 2.5.5

Type: Bug Priority: Major - P3
Reporter: Matt Kangas Assignee: Matt Dannenberg
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
duplicates SERVER-12555 OpDebug::planSummary std::string may ... Closed
Related
is related to SERVER-60646 remove ThreadSafeString Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Participants:

 Description   

[ed: original title "'out of memory, printing stack and exiting' during parallel/basic.js on Linux 64-bit DEBUG"]

ProgressMeter is not thread-safe. Because of this, it is possible to crash the server when calling db.currentOp() during a map-reduce or index build.

Threads are permitted to call CurOp::setMessage() on CurOp objects they own. CurOp::setMessage() calls ProgressMeter::setName(), which calls operator= ProgressMeter::_name, which is an std::string.

db.currentOp() calls CurOp::info() on CurOp objects owned by other threads. CurOp::info() calls ProgressMeter::toString(), which performs a copy on the same string above. Doing so while _name is being modified can result in a string with a corrupt length, which can crash the server (e.g. during allocation of a copy, or while reading unmapped memory).



 Comments   
Comment by Matt Dannenberg [ 02/Dec/13 ]

Author:

{u'username': u'dannenberg', u'name': u'matt dannenberg', u'email': u'matt.dannenberg@10gen.com'}

Message: SERVER-11763 switch ProgressMeter's _name to be a ThreadSafeString
Branch: master
https://github.com/mongodb/mongo/commit/dc50cacf30ee57958149aa00171aa0b9015cd01b

Comment by J Rassi [ 18/Nov/13 ]

The following parallel failure exhibits this scenario (evalc.js runs "for ( i=0; i<50000; i++ ){ db.currentOp(); }", while extent2.js runs "for ( i=0; i<100; i++ ) { [...] t.ensureIndex({x:1}); t.drop(); }")

2013/11/18: ffd52e5f46cf Linux 64-bit DEBUG parallel : basic.js

http://buildlogs.mongodb.org/mci_0.9_linux_64_debug/builds/16259/test/parallel_0/basic.js

         S0 Test : jstests/extent2.js ...
2013-11-18T05:53:22.454+0000 [conn29] build index done.  scanned 3 total records. 0 secs
2013-11-18T05:53:22.455+0000 [conn29] CMD: drop test_extent2.foo
tcmalloc: large alloc 1073750016 bytes == 0x7fb11ffd2000 @ 
2013-11-18 00:53:26 EST	
tcmalloc: large alloc 2147491840 bytes == 0x7fb09fecc000 @ 
2013-11-18 00:53:28 EST	
2013-11-18T05:53:28.344+0000 [clientcursormon] mem (MB) res:4764 virt:13666
2013-11-18T05:53:28.344+0000 [clientcursormon]  mapped (incl journal view):3552
2013-11-18T05:53:28.344+0000 [clientcursormon]  connections:6
tcmalloc: large alloc 4294975488 bytes == 0x7faf9fcca000 @ 
2013-11-18 00:53:36 EST	
tcmalloc: large alloc 8589942784 bytes == 0x7fad9f8c0000 @ 
2013-11-18 00:54:02 EST	
tcmalloc: large alloc 4611686018427396096 bytes == (nil) @ 
2013-11-18T05:54:02.321+0000 DBClientCursor::init call() failed
out of memory, printing stack and exiting:2013-11-18T05:54:02.225+0000 [conn43] 0x11a48b1 0x770075 0x18c0541 0x7fb29dddf3c9 0x7fb29dde019b 0x7fb29dde05ec 0x7fb29ddda8f1 0x7fb29ddd5ac9 0x11a32d3 0xa3404e 0xbe4c36 0xbe9615 0x781c0d 0x11616c4 0x3e42607851 0x3e41ee894d 
 ./mongod(_ZN5mongo15printStackTraceERSo+0x21) [0x11a48b1]
 ./mongod(_ZN5mongo14my_new_handlerEv+0x55) [0x770075]
 ./mongod(tc_new+0x51) [0x18c0541]
 /usr/lib64/libstdc++.so.6(_ZNSs4_Rep9_S_createEmmRKSaIcE+0x59) [0x7fb29dddf3c9]
 /usr/lib64/libstdc++.so.6(_ZNSs4_Rep8_M_cloneERKSaIcEm+0x2b) [0x7fb29dde019b]
 /usr/lib64/libstdc++.so.6(_ZNSs7reserveEm+0x3c) [0x7fb29dde05ec]
 /usr/lib64/libstdc++.so.6(_ZNSt15basic_stringbufIcSt11char_traitsIcESaIcEE8overflowEi+0xb1) [0x7fb29ddda8f1]
 /usr/lib64/libstdc++.so.6(_ZSt16__ostream_insertIcSt11char_traitsIcEERSt13basic_ostreamIT_T0_ES6_PKS3_l+0x349) [0x7fb29ddd5ac9]
 ./mongod(_ZNK5mongo13ProgressMeter8toStringEv+0xc3) [0x11a32d3]
 ./mongod(_ZN5mongo5CurOp4infoEv+0x96e) [0xa3404e]
 ./mongod(_ZN5mongo9inProgCmdERNS_7MessageERNS_10DbResponseE+0x696) [0xbe4c36]
 ./mongod(_ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE+0x865) [0xbe9615]
 ./mongod(_ZN5mongo16MyMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0x9d) [0x781c0d]
 ./mongod(_ZN5mongo17PortMessageServer17handleIncomingMsgEPv+0x514) [0x11616c4]
 /lib64/libpthread.so.0() [0x3e42607851]
 /lib64/libc.so.6(clone+0x6d) [0x3e41ee894d]
2013-11-18T05:54:02.321+0000 Socket say send() errno:104 Connection reset by peer 127.0.0.1:27999
2013-11-18T05:54:02.321+0000 DBClientCursor::init call() failed
sh21972| 2013-11-18T05:54:02.321+0000 DBClientCursor::init call() failed
2013-11-18T05:54:02.322+0000 Socket recv() errno:104 Connection reset by peer 127.0.0.1:27999
2013-11-18T05:54:02.322+0000 SocketException: remote: 127.0.0.1:27999 error: 9001 socket exception [RECV_ERROR] server [127.0.0.1:27999] 
2013-11-18T05:54:02.322+0000 DBClientCursor::init call() failed
2013-11-18T05:54:02.324+0000 Error: error doing query: failed at src/mongo/shell/query.js:81
2013-11-18T05:54:02.325+0000 Error: error doing query: failed at src/mongo/shell/collection.js:55
sh21972| 2013-11-18T05:54:02.324+0000 Error: error doing query: failed at src/mongo/shell/collection.js:55
2013-11-18T05:54:02.325+0000 Error: socket exception [SEND_ERROR] for 127.0.0.1:27999 at src/mongo/shell/collection.js:228
********** Parallel Test FAILED: Error: error loading js file: jstests/evalc.js
********** Parallel Test FAILED: Error: error loading js file: jstests/extent2.js
********** Parallel Test FAILED: Error: error loading js file: jstests/indexe.js
********** Parallel Test FAILED: Error: error loading js file: jstests/remove7.js

Demangled stack trace:

 ./mongod(mongo::printStackTrace(std::basic_ostream<char, std::char_traits<char> >&)+0x21) [0x11a48b1]
 ./mongod(mongo::my_new_handler()+0x55) [0x770075]
 ./mongod(tc_new+0x51) [0x18c0541]
 /usr/lib64/libstdc++.so.6(std::basic_string<char, std::char_traits<char>, std::allocator<char> >::_Rep::_S_create(unsigned long, unsigned long, std::allocator<char> const&)+0x59) [0x7fb29dddf3c9]
 /usr/lib64/libstdc++.so.6(std::basic_string<char, std::char_traits<char>, std::allocator<char> >::_Rep::_M_clone(std::allocator<char> const&, unsigned long)+0x2b) [0x7fb29dde019b]
 /usr/lib64/libstdc++.so.6(std::basic_string<char, std::char_traits<char>, std::allocator<char> >::reserve(unsigned long)+0x3c) [0x7fb29dde05ec]
 /usr/lib64/libstdc++.so.6(std::basic_stringbuf<char, std::char_traits<char>, std::allocator<char> >::overflow(int)+0xb1) [0x7fb29ddda8f1]
 /usr/lib64/libstdc++.so.6(std::basic_ostream<char, std::char_traits<char> >& std::__ostream_insert<char, std::char_traits<char> >(std::basic_ostream<char, std::char_traits<char> >&, char const*, long)+0x349) [0x7fb29ddd5ac9]
 ./mongod(mongo::ProgressMeter::toString() const+0xc3) [0x11a32d3]
 ./mongod(mongo::CurOp::info()+0x96e) [0xa3404e]
 ./mongod(mongo::inProgCmd(mongo::Message&, mongo::DbResponse&)+0x696) [0xbe4c36]
 ./mongod(mongo::assembleResponse(mongo::Message&, mongo::DbResponse&, mongo::HostAndPort const&)+0x865) [0xbe9615]
 ./mongod(mongo::MyMessageHandler::process(mongo::Message&, mongo::AbstractMessagingPort*, mongo::LastError*)+0x9d) [0x781c0d]
 ./mongod(mongo::PortMessageServer::handleIncomingMsg(void*)+0x514) [0x11616c4]

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