MongoDB hangs up on shutdown

mongodb

I'm having issues with MongoDB replica set: when I try to shutdown a MongoDB instance, it hangs up and ends up being killed by systemd. When it starts again, it finds itself way behind the primary, although it was lagging less than 30 sec before the restart, and thus requires full resync to recover.

Log looks like so:

Jul 11 21:38:19 mongo-rs0-1 systemd[1]: Stopping mongo_rs0.service...
Jul 11 21:38:19 mongo-rs0-1 numactl[26076]: MongoDB shell version v3.4.5
Jul 11 21:38:19 mongo-rs0-1 numactl[26076]: connecting to: mongodb://127.0.0.1:27017/admin
Jul 11 21:38:19 mongo-rs0-1 mongod.27017[10705]: [thread1] connection accepted from 127.0.0.1:51524 #11301 (32 connections now open)
Jul 11 21:38:19 mongo-rs0-1 mongod.27017[10705]: [conn11301] received client metadata from 127.0.0.1:51524 conn11301: { application: { name: "MongoDB Shell" }, driver: { name: "MongoDB Internal Client", version: "3.4.5" }, os: { type: "Linux", name: "Ubuntu", architecture: "x86_64", version: "16.04" } }
Jul 11 21:38:19 mongo-rs0-1 numactl[26076]: MongoDB server version: 3.4.5
Jul 11 21:38:19 mongo-rs0-1 mongod.27017[10705]: [conn11301] terminating, shutdown command received
Jul 11 21:38:19 mongo-rs0-1 mongod.27017[10705]: [conn11301] shutdown: going to close listening sockets...
Jul 11 21:38:19 mongo-rs0-1 mongod.27017[10705]: [conn11301] closing listening socket: 7
Jul 11 21:38:19 mongo-rs0-1 mongod.27017[10705]: [conn11301] closing listening socket: 8
Jul 11 21:38:19 mongo-rs0-1 mongod.27017[10705]: [conn11301] removing socket file: /tmp/mongodb-27017.sock
Jul 11 21:38:19 mongo-rs0-1 mongod.27017[10705]: [conn11301] shutdown: going to flush diaglog...
Jul 11 21:38:19 mongo-rs0-1 mongod.27017[10705]: [conn11301] shutting down replication subsystems
Jul 11 21:38:19 mongo-rs0-1 mongod.27017[10705]: [conn11301] Stopping replication reporter thread
Jul 11 21:38:19 mongo-rs0-1 mongod.27017[10705]: [SyncSourceFeedback] SyncSourceFeedback error sending update to X.X.X.X:27017: CallbackCanceled: Reporter no longer valid
Jul 11 21:38:19 mongo-rs0-1 mongod.27017[10705]: [conn11301] Stopping replication fetcher thread
Jul 11 21:38:19 mongo-rs0-1 mongod.27017[10705]: [conn11301] Stopping replication applier thread
Jul 11 21:38:19 mongo-rs0-1 mongod.27017[10705]: [NetworkInterfaceASIO-RS-0] Ending connection to host X.X.X.X:27017 due to bad connection status; 1 connections to that host remain open
Jul 11 21:38:19 mongo-rs0-1 mongod.27017[10705]: [rsBackgroundSync] Replication producer stopped after oplog fetcher finished returning a batch from our sync source.  Abandoning this batch of oplog entries and re-evaluating our sync source.
Jul 11 21:38:19 mongo-rs0-1 mongod.27017[10705]: [conn11301] Stopping replication storage threads
Jul 11 21:38:19 mongo-rs0-1 mongod.27017[10705]: [conn11301] Shutting down full-time diagnostic data capture
Jul 11 21:38:19 mongo-rs0-1 mongod.27017[10705]: [conn11301] WiredTigerKVEngine shutting down
Jul 11 21:39:48 mongo-rs0-1 systemd[1]: mongo_rs0.service: Stopping timed out. Terminating.
Jul 11 21:39:48 mongo-rs0-1 mongod.27017[10705]: [signalProcessingThread] got signal 15 (Terminated), will terminate after current cmd ends
Jul 11 21:41:17 mongo-rs0-1 systemd[1]: mongo_rs0.service: State 'stop-sigterm' timed out. Killing.
Jul 11 21:41:21 mongo-rs0-1 systemd[1]: mongo_rs0.service: Main process exited, code=killed, status=9/KILL
Jul 11 21:41:21 mongo-rs0-1 systemd[1]: Stopped mongo_rs0.service.

Some details about my setup:

  • MongoDB version: 3.4.5.
  • Replica set of 5 members.
  • Database size: 160 Gb.
  • Each MongoDB instance runs on a separate Ubuntu 16.04 server.
  • Machines are hosted on Azure.
  • tcp_keepalive_time is set to 120 following MongoDB Production Notes.
  • RAM: 112 Gb total. 46 Gb are used by MongoDB, 65 Gb is buff/cache.
  • Disk: local SSD 224 Gb.
  • Filesystem: /dev/sdb1 /mnt xfs rw,noatime,attr2,inode64,noquota 0 0
  • All nodes are in the same virtual network.

Would appreciate your help!

UPD. While MongoDB is trying to shut downm strace looks like this:

[pid 19427] clock_gettime(CLOCK_REALTIME, {1499999373, 643829993}) = 0
[pid 19427] gettimeofday({1499999373, 643888}, NULL) = 0
[pid 19427] clock_gettime(CLOCK_REALTIME, {1499999373, 643934714}) = 0
[pid 19427] futex(0x55b9eeb5c888, FUTEX_WAKE_PRIVATE, 1) = 0
[pid 19427] futex(0x55b9eeb5c8b4, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 18378657, {1499999373, 653934714}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
[pid 19427] clock_gettime(CLOCK_REALTIME, {1499999373, 654170663}) = 0
[pid 19427] gettimeofday({1499999373, 654194}, NULL) = 0
[pid 19427] clock_gettime(CLOCK_REALTIME, {1499999373, 654225234}) = 0
[pid 19427] futex(0x55b9eeb5c888, FUTEX_WAKE_PRIVATE, 1) = 0
[pid 19427] futex(0x55b9eeb5c8b4, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 18378659, {1499999373, 664225234}, ffffffff) = -1 ETIMEDOUT (Connection timed out)
[pid 19427] clock_gettime(CLOCK_REALTIME, {1499999373, 664494649}) = 0
[pid 19427] gettimeofday({1499999373, 664546}, NULL) = 0
[pid 19427] clock_gettime(CLOCK_REALTIME, {1499999373, 664597059}) = 0
[pid 19427] futex(0x55b9eeb5c888, FUTEX_WAKE_PRIVATE, 1) = 0
[pid 19427] futex(0x55b9eeb5c8b4, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 18378661, {1499999373, 674597059}, ffffffff) = -1 ETIMEDOUT (Connection timed out)

UPD2. I also did db.setLogLevel(2) before shutdown and the output looks like this. Those exceptions just keep coming indefinitely.

Jul 14 18:51:32 mongo-RS-2-1 mongod[24504]: 2017-07-14T18:51:32.239+0000 D COMMAND  [conn23] run command admin.$cmd { ismaster: 1 }
Jul 14 18:51:32 mongo-RS-2-1 mongod[24504]: 2017-07-14T18:51:32.239+0000 D -        [conn23] User Assertion: 11600:interrupted at shutdown src/mongo/db/operation_context.cpp 159
Jul 14 18:51:32 mongo-RS-2-1 mongod[24504]: 2017-07-14T18:51:32.239+0000 D COMMAND  [conn23] assertion while executing command 'ismaster' on database 'admin' with arguments '{ ismaster: 1 }' and metadata '{}': 11600 interrupted at shutdown
Jul 14 18:51:32 mongo-RS-2-1 mongod[24504]: 2017-07-14T18:51:32.239+0000 I COMMAND  [conn23] command admin.$cmd command: isMaster { ismaster: 1 } exception: interrupted at shutdown code:11600 numYields:0 reslen:119 locks:{} protocol:op_query 0ms
Jul 14 18:51:32 mongo-RS-2-1 mongod[24504]: 2017-07-14T18:51:32.297+0000 D COMMAND  [conn15] run command admin.$cmd { ismaster: 1 }
Jul 14 18:51:32 mongo-RS-2-1 mongod[24504]: 2017-07-14T18:51:32.297+0000 D -        [conn15] User Assertion: 11600:interrupted at shutdown src/mongo/db/operation_context.cpp 159
Jul 14 18:51:32 mongo-RS-2-1 mongod[24504]: 2017-07-14T18:51:32.297+0000 D COMMAND  [conn15] assertion while executing command 'ismaster' on database 'admin' with arguments '{ ismaster: 1 }' and metadata '{}': 11600 interrupted at shutdown
Jul 14 18:51:32 mongo-RS-2-1 mongod[24504]: 2017-07-14T18:51:32.297+0000 I COMMAND  [conn15] command admin.$cmd command: isMaster { ismaster: 1 } exception: interrupted at shutdown code:11600 numYields:0 reslen:119 locks:{} protocol:op_query 0ms
Jul 14 18:51:32 mongo-RS-2-1 mongod[24504]: 2017-07-14T18:51:32.309+0000 D COMMAND  [conn24] run command admin.$cmd { ismaster: 1 }
Jul 14 18:51:32 mongo-RS-2-1 mongod[24504]: 2017-07-14T18:51:32.310+0000 D -        [conn24] User Assertion: 11600:interrupted at shutdown src/mongo/db/operation_context.cpp 159
...

Best Answer

Upgrading to 3.4.6 helped. The issue is now resolved.

Quick summary:

  • MongoDB used realtime clock as if it is monotonic while it is not by design (see ticket WT-3327).
  • As a result, when realtime clock fluctuated backwards far enough, MongoDB could get into an infinite sleep.
  • Normally, accuracy of realtime clock is pretty good so this did not cause issues on most of the systems.
  • However, realtime clock is very inaccurate on Azure VMs due to Hyper-V virtualization's side effects.
  • This bug could cause other operational issues too, specifically, broken rotation of journal files (see related bugs in the ticket WT-3327 referenced above).
Related Question