Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-9869

C++ driver crash when mongodb is shutdowned

    • Type: Icon: Bug Bug
    • Resolution: Done
    • Priority: Icon: Major - P3 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:

      { getlasterror: 1, w: 2, wtimeout: 0 }

      ntoreturn:1 keyUpdates:0 reslen:135 85934181ms
      Sat May 11 10:00:42 [conn31] command vmdb.$cmd command:

      { getlasterror: 1, w: 2, wtimeout: 0 }

      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" : [

      { "_id" : 0, "host" : "openuc.ezuce.com:27017", "priority" : 2 }

      ]
      }

            Assignee:
            andrew.morrow@mongodb.com Andrew Morrow (Inactive)
            Reporter:
            dtacalau Daniel Stefan Tacalau
            Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

              Created:
              Updated:
              Resolved: