-
Type: Bug
-
Resolution: Done
-
Priority: Major - P3
-
None
-
Affects Version/s: 2.2.3
-
Component/s: Internal Client
-
Labels:None
-
Environment:Linux 3.4.37-40.44.amzn1.x86_64 #1 SMP Thu Mar 21 01:17:08 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux
-
Linux
One of our applications crashed with the following stacktrace from the C++ mongodb driver thread:
Program terminated with signal 6, Aborted.
#0 0x00007fe627b40945 in raise (sig=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
64 return INLINE_SYSCALL (tgkill, 3, pid, selftid, sig);
(gdb) bt
#0 0x00007fe627b40945 in raise (sig=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
#1 0x00007fe627b4225b in abort () at abort.c:92
#2 0x00007fe627b3937e in __assert_fail_base (fmt=<value optimized out>, assertion=0x7fe62af586c4 "!pthread_mutex_lock(&m)",
file=0x7fe62af58790 "/usr/include/boost/thread/pthread/mutex.hpp", line=<value optimized out>, function=<value optimized out>) at assert.c:96
#3 0x00007fe627b39422 in __assert_fail (assertion=0x7fe62af586c4 "!pthread_mutex_lock(&m)", file=0x7fe62af58790 "/usr/include/boost/thread/pthread/mutex.hpp", line=125,
function=0x7fe62af65100 "void boost::timed_mutex::lock()") at assert.c:105
#4 0x00007fe62af3f2c3 in lock (this=0x2158180, t=0x0) at /usr/include/boost/thread/pthread/mutex.hpp:125
#5 lock (this=0x2158180, t=0x0) at /usr/include/boost/thread/locks.hpp:349
#6 unique_lock (this=0x2158180, t=0x0) at /usr/include/boost/thread/locks.hpp:227
#7 scoped_lock (this=0x2158180, t=0x0) at src/mongo/util/concurrency/mutex.h:104
#8 mongo::Logstream::flush (this=0x2158180, t=0x0) at src/mongo/util/log.cpp:357
#9 0x00007fe62af3fb8e in mongo::Logstream::operator<< (this=<value optimized out>, _endl=<value optimized out>) at src/mongo/util/log.h:307
#10 0x00007fe62aecb128 in mongo::ReplicaSetMonitor::_checkConnection (this=0x1f49920, conn=0x1f94c80, maybePrimary=<value optimized out>, verbose=true, nodesOffset=0)
at src/mongo/client/dbclient_rs.cpp:766
#11 0x00007fe62aecb66c in mongo::ReplicaSetMonitor::_check (this=0x1f49920, checkAllSecondaries=true) at src/mongo/client/dbclient_rs.cpp:814
#12 0x00007fe62aecf54c in mongo::ReplicaSetMonitor::check (this=0x1f49920, checkAllSecondaries=true) at src/mongo/client/dbclient_rs.cpp:955
#13 0x00007fe62aecf7a3 in mongo::ReplicaSetMonitor::checkAll (checkAllSecondaries=true) at src/mongo/client/dbclient_rs.cpp:322
#14 0x00007fe62aed7f74 in mongo::ReplicaSetMonitorWatcher::run (this=<value optimized out>) at src/mongo/client/dbclient_rs.cpp:202
#15 0x00007fe62af2c3db in mongo::BackgroundJob::jobBody (this=0x7fe62b196000, status=...) at src/mongo/util/background.cpp:64
#16 0x00007fe62af2e309 in operator() (this=<value optimized out>) at /usr/include/boost/bind/mem_fn_template.hpp:162
#17 operator()<boost::_mfi::mf1<void, mongo::BackgroundJob, boost::shared_ptr<mongo::BackgroundJob::JobStatus> >, boost::_bi::list0> (this=<value optimized out>)
at /usr/include/boost/bind/bind.hpp:306
#18 operator() (this=<value optimized out>) at /usr/include/boost/bind/bind_template.hpp:20
#19 boost::detail::thread_data<boost::_bi::bind_t<void, boost::_mfi::mf1<void, mongo::BackgroundJob, boost::shared_ptr<mongo::BackgroundJob::JobStatus> >, boost::_bi::list2<boost::_bi::value<mongo::BackgroundJob*>, boost::_bi::value<boost::shared_ptr<mongo::BackgroundJob::JobStatus> > > > >::run (this=<value optimized out>)
at /usr/include/boost/thread/detail/thread.hpp:56
#20 0x00007fe62885fd97 in boost::(anonymous namespace)::thread_proxy (param=<value optimized out>) at /usr/src/debug/boost-1.41.0.cmake0/libs/thread/src/pthread/thread.cpp:120
#21 0x00007fe628640c6b in start_thread (arg=0x7fe620d04700) at pthread_create.c:301
#22 0x00007fe627bee5ed in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:115
(gdb)
It seems that the crash happened when mongodb was shutdowned. There is a lot of inactivity in mongodb log until the moment of the shutdown:
Sat May 11 10:00:42 got signal 15 (Terminated), will terminate after current cmd ends
Sat May 11 10:00:42 [interruptThread] now exiting
Sat May 11 10:00:42 dbexit:
Sat May 11 10:00:42 [interruptThread] shutdown: going to close listening sockets...
Sat May 11 10:00:42 [interruptThread] closing listening socket: 6
Sat May 11 10:00:42 [interruptThread] closing listening socket: 7
Sat May 11 10:00:42 [interruptThread] removing socket file: /tmp/mongodb-27017.sock
Sat May 11 10:00:42 [conn15] got request after shutdown()
Sat May 11 10:00:42 [conn21] command vmdb.$cmd command:
ntoreturn:1 keyUpdates:0 reslen:135 85934181ms
Sat May 11 10:00:42 [conn31] command vmdb.$cmd command:
ntoreturn:1 keyUpdates:0 reslen:135 85812168ms
Sat May 11 10:00:42 [conn21] SocketException handling request, closing client connection: 9001 socket exception [2] server [172.31.1.9:48545]
Sat May 11 10:00:42 [interruptThread] shutdown: going to flush diaglog...
Sat May 11 10:00:42 [interruptThread] shutdown: going to close sockets...
Sat May 11 10:00:42 [interruptThread] shutdown: waiting for fs preallocator...
Sat May 11 10:00:42 [interruptThread] shutdown: lock for final commit...
Sat May 11 10:00:42 [interruptThread] shutdown: final commit...
Sat May 11 10:00:42 [conn31] SocketException handling request, closing client connection: 9001 socket exception [2] server [172.31.1.9:48591]
Sat May 11 10:00:42 [interruptThread] shutdown: closing all files...
Sat May 11 10:00:42 [interruptThread] closeAllFiles() finished
Sat May 11 10:00:42 [interruptThread] journalCleanup...
Sat May 11 10:00:42 [interruptThread] removeJournalFiles
Sat May 11 10:00:42 [interruptThread] shutdown: removing fs lock...
Sat May 11 10:00:42 dbexit: really exiting now
warning: bind_ip of 0.0.0.0 is unnecessary; listens on all ips by default
forked process: 1216
all output going to: /var/log/mongodb/mongodb.log
log file [/var/log/mongodb/mongodb.log] exists; copied to temporary file [/var/log/mongodb/mongodb.log.2013-05-11T10-01-39]
child process started successfully, parent exiting
Mongodb has only one node:
mongo
MongoDB shell version: 2.2.3
connecting to: test
sipxecs:PRIMARY> rs.config()
{
"_id" : "sipxecs",
"version" : 1,
"members" : [
]
}