[SERVER-32598] sudo systemctl start mongod is a noop when server shutdown using a separate method Created: 09/Jan/18  Updated: 10/Jan/18  Resolved: 10/Jan/18

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

Type: Bug Priority: Major - P3
Reporter: Vick Mena (Inactive) Assignee: Mathew Robinson (Inactive)
Resolution: Won't Fix Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Centos 7.4


Backwards Compatibility: Fully Compatible
Operating System: ALL
Steps To Reproduce:
  1. sudo systemctl start mongod
  2. mongo --eval 'db.getSiblingDB("admin").shutdownServer()'
  3. sudo systemctl start mongod
  4. mongo
Sprint: Build Expedite
Participants:
Case:

 Description   

Service is not flagged as down when the server is shutdown via kill or db.shutdownServer().

One workaround is to restart the service instead of starting it: sudo systemctl restart mongod

[root@centos74 ~]# systemctl status -l mongod
● mongod.service - SYSV: Mongo is a scalable, document-oriented database.
   Loaded: loaded (/etc/rc.d/init.d/mongod; bad; vendor preset: disabled)
   Active: active (exited) since Tue 2018-01-09 16:01:15 UTC; 3min 46s ago
     Docs: man:systemd-sysv-generator(8)
  Process: 7448 ExecStop=/etc/rc.d/init.d/mongod stop (code=exited, status=0/SUCCESS)
  Process: 7464 ExecStart=/etc/rc.d/init.d/mongod start (code=exited, status=0/SUCCESS)
 Main PID: 4133 (code=killed, signal=KILL)
 
Jan 09 16:01:15 centos74.vagrant.dev systemd[1]: Starting SYSV: Mongo is a scalable, document-oriented database....
Jan 09 16:01:15 centos74.vagrant.dev runuser[7476]: pam_unix(runuser:session): session opened for user mongod by (uid=0)
Jan 09 16:01:15 centos74.vagrant.dev mongod[7464]: Starting mongod: [  OK  ]
Jan 09 16:01:15 centos74.vagrant.dev systemd[1]: Started SYSV: Mongo is a scalable, document-oriented database..
 
[root@centos74 ~]# pgrep -lfa mongod
 
[root@centos74 ~]# mongo
MongoDB shell version: 3.2.18
connecting to: test
2018-01-09T16:05:18.965+0000 W NETWORK  [thread1] Failed to connect to 127.0.0.1:27017, in(checking socket for error after poll), reason: errno:111 Connection refused
2018-01-09T16:05:18.965+0000 E QUERY    [thread1] Error: couldn't connect to server 127.0.0.1:27017, connection attempt failed :
connect@src/mongo/shell/mongo.js:229:14
@(connect):1:6
 
exception: connect failed

Host details:

cat /etc/redhat-release
CentOS Linux release 7.4.1708 (Core)
 
uname -a
Linux centos74.vagrant.dev 3.10.0-693.5.2.el7.x86_64 #1 SMP Fri Oct 20 20:32:50 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
 
systemctl  --version
systemd 219
+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ -LZ4 -SECCOMP +BLKID +ELFUTILS +KMOD +IDN
 
rpm -qva | grep mongo
mongodb-enterprise-shell-3.2.18-1.el7.x86_64
mongodb-enterprise-mongos-3.2.18-1.el7.x86_64
mongodb-enterprise-tools-3.2.18-1.el7.x86_64
mongodb-enterprise-3.2.18-1.el7.x86_64
mongodb-enterprise-server-3.2.18-1.el7.x86_64



 Comments   
Comment by Mathew Robinson (Inactive) [ 10/Jan/18 ]

Ok so I was able to reproduce this on 3.2.18 on RHEL 7.0:

[root@ip-10-157-172-54 ~]# systemctl start mongod
[root@ip-10-157-172-54 ~]# ps -ef | grep mongo
mongod    12074      1  0 20:31 ?        00:00:01 /usr/bin/mongod -f /etc/mongod.conf
root      12414  12194  0 20:39 pts/0    00:00:00 grep --color=auto mongo
[root@ip-10-157-172-54 ~]# systemctl status mongod
● mongod.service - SYSV: Mongo is a scalable, document-oriented database.
   Loaded: loaded (/etc/rc.d/init.d/mongod; bad; vendor preset: disabled)
   Active: active (running) since Wed 2018-01-10 20:31:45 UTC; 7min ago
     Docs: man:systemd-sysv-generator(8)
 Main PID: 12074 (mongod)
   CGroup: /system.slice/mongod.service
           └─12074 /usr/bin/mongod -f /etc/mongod.conf
 
Jan 10 20:31:41 ip-10-157-172-54.ec2.internal systemd[1]: Starting High-performance, schema-free document-oriented database...
Jan 10 20:31:41 ip-10-157-172-54.ec2.internal mongod[12072]: about to fork child process, waiting until server is ready for connections.
Jan 10 20:31:41 ip-10-157-172-54.ec2.internal mongod[12072]: forked process: 12074
Jan 10 20:31:45 ip-10-157-172-54.ec2.internal mongod[12072]: child process started successfully, parent exiting
Jan 10 20:31:45 ip-10-157-172-54.ec2.internal systemd[1]: Started High-performance, schema-free document-oriented database.
[root@ip-10-157-172-54 ~]# mongo --eval 'db.getSiblingDB("admin").shutdownServer()'
MongoDB shell version: 3.2.18
connecting to: test
server should be down...
[root@ip-10-157-172-54 ~]# systemctl status mongod
● mongod.service - SYSV: Mongo is a scalable, document-oriented database.
   Loaded: loaded (/etc/rc.d/init.d/mongod; bad; vendor preset: disabled)
   Active: active (exited) since Wed 2018-01-10 20:31:45 UTC; 7min ago
     Docs: man:systemd-sysv-generator(8)
 Main PID: 12074 (code=exited, status=0/SUCCESS)
 
Jan 10 20:31:41 ip-10-157-172-54.ec2.internal systemd[1]: Starting High-performance, schema-free document-oriented database...
Jan 10 20:31:41 ip-10-157-172-54.ec2.internal mongod[12072]: about to fork child process, waiting until server is ready for connections.
Jan 10 20:31:41 ip-10-157-172-54.ec2.internal mongod[12072]: forked process: 12074
Jan 10 20:31:45 ip-10-157-172-54.ec2.internal mongod[12072]: child process started successfully, parent exiting
Jan 10 20:31:45 ip-10-157-172-54.ec2.internal systemd[1]: Started High-performance, schema-free document-oriented database.
[root@ip-10-157-172-54 ~]# ls /var/run/mongodb/
mongod.pid
[root@ip-10-157-172-54 ~]# ps -ef | grep mongo
root      12429  12194  0 20:40 pts/0    00:00:00 grep --color=auto mongo
[root@ip-10-157-172-54 ~]#

It looks like when Mongo exits it's not removing the pid file. I tested this on 3.6.2 and when you shut down the database the PID file is removed and works as expected:

[root@ip-10-157-172-54 ~]# systemctl start mongod
[root@ip-10-157-172-54 ~]# systemctl status mongod
● mongod.service - High-performance, schema-free document-oriented database
   Loaded: loaded (/usr/lib/systemd/system/mongod.service; enabled; vendor preset: disabled)
   Active: active (running) since Wed 2018-01-10 20:20:10 UTC; 10min ago
     Docs: https://docs.mongodb.org/manual
  Process: 11990 ExecStart=/usr/bin/mongod $OPTIONS (code=exited, status=0/SUCCESS)
  Process: 11987 ExecStartPre=/usr/bin/chmod 0755 /var/run/mongodb (code=exited, status=0/SUCCESS)
  Process: 11984 ExecStartPre=/usr/bin/chown mongod:mongod /var/run/mongodb (code=exited, status=0/SUCCESS)
  Process: 11981 ExecStartPre=/usr/bin/mkdir -p /var/run/mongodb (code=exited, status=0/SUCCESS)
 Main PID: 11992 (mongod)
   CGroup: /system.slice/mongod.service
           └─11992 /usr/bin/mongod -f /etc/mongod.conf
 
Jan 10 20:20:00 ip-10-157-172-54.ec2.internal systemd[1]: Starting High-performance, schema-free document-oriented database...
Jan 10 20:20:00 ip-10-157-172-54.ec2.internal mongod[11990]: about to fork child process, waiting until server is ready for connections.
Jan 10 20:20:00 ip-10-157-172-54.ec2.internal mongod[11990]: forked process: 11992
Jan 10 20:20:10 ip-10-157-172-54.ec2.internal mongod[11990]: child process started successfully, parent exiting
Jan 10 20:20:10 ip-10-157-172-54.ec2.internal systemd[1]: Started High-performance, schema-free document-oriented database.
[root@ip-10-157-172-54 ~]# mongo --eval 'db.getSiblingDB("admin").shutdownServer()'
MongoDB shell version v3.6.2
connecting to: mongodb://127.0.0.1:27017
MongoDB server version: 3.6.2
server should be down...
[root@ip-10-157-172-54 ~]# systemctl status mongod
● mongod.service - High-performance, schema-free document-oriented database
   Loaded: loaded (/usr/lib/systemd/system/mongod.service; enabled; vendor preset: disabled)
   Active: inactive (dead) since Wed 2018-01-10 20:31:16 UTC; 4s ago
     Docs: https://docs.mongodb.org/manual
  Process: 11990 ExecStart=/usr/bin/mongod $OPTIONS (code=exited, status=0/SUCCESS)
  Process: 11987 ExecStartPre=/usr/bin/chmod 0755 /var/run/mongodb (code=exited, status=0/SUCCESS)
  Process: 11984 ExecStartPre=/usr/bin/chown mongod:mongod /var/run/mongodb (code=exited, status=0/SUCCESS)
  Process: 11981 ExecStartPre=/usr/bin/mkdir -p /var/run/mongodb (code=exited, status=0/SUCCESS)
 Main PID: 11992 (code=exited, status=0/SUCCESS)
 
Jan 10 20:20:00 ip-10-157-172-54.ec2.internal systemd[1]: Starting High-performance, schema-free document-oriented database...
Jan 10 20:20:00 ip-10-157-172-54.ec2.internal mongod[11990]: about to fork child process, waiting until server is ready for connections.
Jan 10 20:20:00 ip-10-157-172-54.ec2.internal mongod[11990]: forked process: 11992
Jan 10 20:20:10 ip-10-157-172-54.ec2.internal mongod[11990]: child process started successfully, parent exiting
Jan 10 20:20:10 ip-10-157-172-54.ec2.internal systemd[1]: Started High-performance, schema-free document-oriented database.
[root@ip-10-157-172-54 ~]# ls /var/run/mongodb/
[root@ip-10-157-172-54 ~]# systemctl start mongod
[root@ip-10-157-172-54 ~]# ps -ef | grep mongo
mongod    12074      1  5 20:31 ?        00:00:00 /usr/bin/mongod -f /etc/mongod.conf
root      12102  11560  0 20:31 pts/0    00:00:00 grep --color=auto mongo
[root@ip-10-157-172-54 ~]# mongo
MongoDB shell version v3.6.2
connecting to: mongodb://127.0.0.1:27017
MongoDB server version: 3.6.2
Server has startup warnings:
2018-01-10T20:31:41.189+0000 I STORAGE  [initandlisten]
2018-01-10T20:31:41.189+0000 I STORAGE  [initandlisten] ** WARNING: Using the XFS filesystem is strongly recommended with the WiredTiger storage engine
2018-01-10T20:31:41.189+0000 I STORAGE  [initandlisten] **          See http://dochub.mongodb.org/core/prodnotes-filesystem
2018-01-10T20:31:45.903+0000 I CONTROL  [initandlisten]
2018-01-10T20:31:45.903+0000 I CONTROL  [initandlisten] ** WARNING: Access control is not enabled for the database.
2018-01-10T20:31:45.903+0000 I CONTROL  [initandlisten] **          Read and write access to data and configuration is unrestricted.
2018-01-10T20:31:45.903+0000 I CONTROL  [initandlisten]
2018-01-10T20:31:45.903+0000 I CONTROL  [initandlisten]
2018-01-10T20:31:45.903+0000 I CONTROL  [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/enabled is 'always'.
2018-01-10T20:31:45.903+0000 I CONTROL  [initandlisten] **        We suggest setting it to 'never'
2018-01-10T20:31:45.903+0000 I CONTROL  [initandlisten]
2018-01-10T20:31:45.903+0000 I CONTROL  [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/defrag is 'always'.
2018-01-10T20:31:45.903+0000 I CONTROL  [initandlisten] **        We suggest setting it to 'never'
2018-01-10T20:31:45.903+0000 I CONTROL  [initandlisten]
> show dbs
admin   0.000GB
config  0.000GB
local   0.000GB
>
bye

What I discovered is that in SERVER-31225 we added Type=forking to the service file. Per the SystemD documentation if the child process is killed SystemD will clean up the PID file, but only if Type=forking is set. As you can see in the output above nothing is cleaning up the PID file when the server is killed.

I spoke to ramon.fernandez and we agreed that since this release is two years old changing the init scripts is too risky. Especially, given that there is a work around of removing the pidfile.

Generated at Thu Feb 08 04:30:43 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.