Journal files not removed after clean shutdown

XMLWordPrintableJSON

    • Type: Bug
    • Resolution: Done
    • Priority: Major - P3
    • None
    • Affects Version/s: 3.2.6
    • Component/s: Storage
    • None
    • ALL
    • Hide 
      [root@miles ~]# cat /etc/centos-release
CentOS Linux release 7.1.1503 (Core)
[root@miles ~]# rpm -qa|grep mongo
mongodb-org-server-3.2.6-1.el7.x86_64
mongodb-org-shell-3.2.6-1.el7.x86_64
mongodb-org-3.2.6-1.el7.x86_64
mongodb-org-mongos-3.2.6-1.el7.x86_64
mongodb-org-tools-3.2.6-1.el7.x86_64

      [root@miles:~]# ls -lah /data/mongo
total 0
drwxr-xr-x 2 mongod mongod  6 May  9 12:20 . 
drwxr-xr-x 4 mongod mongod 27 May  9 12:14 . 
[root@miles ~]# systemctl start mongod

      [root@miles:~root@miles ~]# ls -la /data/mongo/journal
total 307204
drwxr-xr-x 2 mongod mongod       107 May  9 12:20 . 
drwxr-xr-x 4 mongod mongod      4096 May  9 12:20 .. 
-rw-r--r-- 1 mongod mongod 104857728 May  9 12:20 WiredTigerLog.0000000001
-rw-r--r-- 1 mongod mongod 104857728 May  9 12:20 WiredTigerPreplog.0000000001
-rw-r--r-- 1 mongod mongod 104857728 May  9 12:20 WiredTigerPreplog.0000000002

      [root@miles:~]# mongo test
MongoDB shell version: 3.2.6
connecting to: test
Server has startup warnings: 
2016-05-09T12:20:58.812-0300 I CONTROL  [initandlisten] 
2016-05-09T12:20:58.812-0300 I CONTROL  [initandlisten] ** WARNING: soft rlimits too low. rlimits set to 4096 processes, 64000 files. Number of processes should be at least 32000 : 0.5 times number of files.
> db.test.insert({a:1})
WriteResult({ "nInserted" : 1 })
> use admin
switched to db admin
> db.shutdownServer()
server should be down...
2016-05-09T12:21:29.760-0300 I NETWORK  [thread1] trying reconnect to 127.0.0.1:27017 (127.0.0.1) failed
2016-05-09T12:21:29.763-0300 I NETWORK  [thread1] Socket recv() errno:104 Connection reset by peer 127.0.0.1:27017
2016-05-09T12:21:29.763-0300 I NETWORK  [thread1] SocketException: remote: (NONE):0 error: 9001 socket exception [RECV_ERROR] server [127.0.0.1:27017] 
2016-05-09T12:21:29.763-0300 I NETWORK  [thread1] reconnect 127.0.0.1:27017 (127.0.0.1) failed failed

      [root@miles ~]# ps -ef|grep mongod
root     22093 21992  0 12:21 pts/2    00:00:00 grep --color=auto mongod 
[root@miles ~]# ls -lah /data/mongo/journal
total 301M
drwxr-xr-x 2 mongod mongod  107 May  9 12:20 . 
drwxr-xr-x 4 mongod mongod 4.0K May  9 12:21 .. 
-rw-r--r-- 1 mongod mongod 101M May  9 12:21 WiredTigerLog.0000000001
-rw-r--r-- 1 mongod mongod 101M May  9 12:20 WiredTigerPreplog.0000000001
-rw-r--r-- 1 mongod mongod 101M May  9 12:20 WiredTigerPreplog.0000000002

      [root@miles ~]# tail -15 /var/log/mongodb/mongod.log
2016-05-09T12:20:58.814-0300 I NETWORK  [HostnameCanonicalizationWorker] Starting hostname canonicalization worker
2016-05-09T12:20:58.854-0300 I NETWORK  [initandlisten] waiting for connections on port 27017
2016-05-09T12:21:14.655-0300 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:50464 #1 (1 connection now open)
2016-05-09T12:21:29.756-0300 I COMMAND  [conn1] terminating, shutdown command received
2016-05-09T12:21:29.756-0300 I FTDC     [conn1] Shutting down full-time diagnostic data capture
2016-05-09T12:21:29.757-0300 I CONTROL  [conn1] now exiting
2016-05-09T12:21:29.757-0300 I NETWORK  [conn1] shutdown: going to close listening sockets...
2016-05-09T12:21:29.757-0300 I NETWORK  [conn1] closing listening socket: 6
2016-05-09T12:21:29.757-0300 I NETWORK  [conn1] closing listening socket: 7
2016-05-09T12:21:29.757-0300 I NETWORK  [conn1] removing socket file: /tmp/mongodb-27017.sock
2016-05-09T12:21:29.757-0300 I NETWORK  [conn1] shutdown: going to flush diaglog...
2016-05-09T12:21:29.757-0300 I NETWORK  [conn1] shutdown: going to close sockets...
2016-05-09T12:21:29.758-0300 I STORAGE  [conn1] WiredTigerKVEngine shutting down
2016-05-09T12:21:29.936-0300 I STORAGE  [conn1] shutdown: removing fs lock...
2016-05-09T12:21:29.936-0300 I CONTROL  [conn1] dbexit:  rc: 0

      [root@miles ~]# cat /etc/mongod.conf
# mongod.conf

# for documentation of all options, see:
#   http://docs.mongodb.org/manual/reference/configuration-options/

# where to write logging data.
systemLog:
  destination: file
  logAppend: true
  path: /var/log/mongodb/mongod.log

# Where and how to store data.
storage:
#  dbPath: /var/lib/mongo
  dbPath: /data/mongo
  journal:
    enabled: true
#  engine:
#  mmapv1:
#  wiredTiger:

# how the process runs
processManagement:
  fork: true  # fork and run in background
  pidFilePath: /var/run/mongodb/mongod.pid  # location of pidfile

# network interfaces
net:
  port: 27017
  bindIp: 127.0.0.1  # Listen to local interface only, comment to listen on all interfaces.


#security:

#operationProfiling:

#replication:

#sharding:

## Enterprise-Only Options

#auditLog:

#snmp:
      Show
      [root@miles ~]# cat /etc/centos-release CentOS Linux release 7.1.1503 (Core) [root@miles ~]# rpm -qa|grep mongo mongodb-org-server-3.2.6-1.el7.x86_64 mongodb-org-shell-3.2.6-1.el7.x86_64 mongodb-org-3.2.6-1.el7.x86_64 mongodb-org-mongos-3.2.6-1.el7.x86_64 mongodb-org-tools-3.2.6-1.el7.x86_64 [root@miles:~]# ls -lah /data/mongo total 0 drwxr-xr-x 2 mongod mongod 6 May 9 12:20 . drwxr-xr-x 4 mongod mongod 27 May 9 12:14 . [root@miles ~]# systemctl start mongod [root@miles:~root@miles ~]# ls -la /data/mongo/journal total 307204 drwxr-xr-x 2 mongod mongod 107 May 9 12:20 . drwxr-xr-x 4 mongod mongod 4096 May 9 12:20 .. -rw-r--r-- 1 mongod mongod 104857728 May 9 12:20 WiredTigerLog.0000000001 -rw-r--r-- 1 mongod mongod 104857728 May 9 12:20 WiredTigerPreplog.0000000001 -rw-r--r-- 1 mongod mongod 104857728 May 9 12:20 WiredTigerPreplog.0000000002 [root@miles:~]# mongo test MongoDB shell version: 3.2.6 connecting to: test Server has startup warnings: 2016-05-09T12:20:58.812-0300 I CONTROL [initandlisten] 2016-05-09T12:20:58.812-0300 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. rlimits set to 4096 processes, 64000 files. Number of processes should be at least 32000 : 0.5 times number of files. > db.test.insert({a:1}) WriteResult({ "nInserted" : 1 }) > use admin switched to db admin > db.shutdownServer() server should be down... 2016-05-09T12:21:29.760-0300 I NETWORK [thread1] trying reconnect to 127.0.0.1:27017 (127.0.0.1) failed 2016-05-09T12:21:29.763-0300 I NETWORK [thread1] Socket recv() errno:104 Connection reset by peer 127.0.0.1:27017 2016-05-09T12:21:29.763-0300 I NETWORK [thread1] SocketException: remote: (NONE):0 error: 9001 socket exception [RECV_ERROR] server [127.0.0.1:27017] 2016-05-09T12:21:29.763-0300 I NETWORK [thread1] reconnect 127.0.0.1:27017 (127.0.0.1) failed failed [root@miles ~]# ps -ef|grep mongod root 22093 21992 0 12:21 pts/2 00:00:00 grep --color=auto mongod [root@miles ~]# ls -lah /data/mongo/journal total 301M drwxr-xr-x 2 mongod mongod 107 May 9 12:20 . drwxr-xr-x 4 mongod mongod 4.0K May 9 12:21 .. -rw-r--r-- 1 mongod mongod 101M May 9 12:21 WiredTigerLog.0000000001 -rw-r--r-- 1 mongod mongod 101M May 9 12:20 WiredTigerPreplog.0000000001 -rw-r--r-- 1 mongod mongod 101M May 9 12:20 WiredTigerPreplog.0000000002 [root@miles ~]# tail -15 /var/log/mongodb/mongod.log 2016-05-09T12:20:58.814-0300 I NETWORK [HostnameCanonicalizationWorker] Starting hostname canonicalization worker 2016-05-09T12:20:58.854-0300 I NETWORK [initandlisten] waiting for connections on port 27017 2016-05-09T12:21:14.655-0300 I NETWORK [initandlisten] connection accepted from 127.0.0.1:50464 #1 (1 connection now open) 2016-05-09T12:21:29.756-0300 I COMMAND [conn1] terminating, shutdown command received 2016-05-09T12:21:29.756-0300 I FTDC [conn1] Shutting down full-time diagnostic data capture 2016-05-09T12:21:29.757-0300 I CONTROL [conn1] now exiting 2016-05-09T12:21:29.757-0300 I NETWORK [conn1] shutdown: going to close listening sockets... 2016-05-09T12:21:29.757-0300 I NETWORK [conn1] closing listening socket: 6 2016-05-09T12:21:29.757-0300 I NETWORK [conn1] closing listening socket: 7 2016-05-09T12:21:29.757-0300 I NETWORK [conn1] removing socket file: /tmp/mongodb-27017.sock 2016-05-09T12:21:29.757-0300 I NETWORK [conn1] shutdown: going to flush diaglog... 2016-05-09T12:21:29.757-0300 I NETWORK [conn1] shutdown: going to close sockets... 2016-05-09T12:21:29.758-0300 I STORAGE [conn1] WiredTigerKVEngine shutting down 2016-05-09T12:21:29.936-0300 I STORAGE [conn1] shutdown: removing fs lock... 2016-05-09T12:21:29.936-0300 I CONTROL [conn1] dbexit: rc: 0 [root@miles ~]# cat /etc/mongod.conf # mongod.conf # for documentation of all options, see: # http://docs.mongodb.org/manual/reference/configuration-options/ # where to write logging data. systemLog: destination: file logAppend: true path: /var/log/mongodb/mongod.log # Where and how to store data. storage: # dbPath: /var/lib/mongo dbPath: /data/mongo journal: enabled: true # engine: # mmapv1: # wiredTiger: # how the process runs processManagement: fork: true # fork and run in background pidFilePath: /var/run/mongodb/mongod.pid # location of pidfile # network interfaces net: port: 27017 bindIp: 127.0.0.1 # Listen to local interface only, comment to listen on all interfaces. #security: #operationProfiling: #replication: #sharding: ## Enterprise-Only Options #auditLog: #snmp:
    • None
    • None
    • None
    • None
    • None
    • None
    • None

      Hello,

      I cannot reproduce the behavior described on this section of the manual:

      https://docs.mongodb.com/v3.2/core/journaling/#journaling-journal-files

      "A clean shutdown removes all the files in the journal directory. A dirty shutdown (crash) leaves files in the journal directory; these are used to automatically recover the database to a consistent state when the mongod process is restarted."

      In 'Steps to Reproduce' there is a transcript of a session where this does not happen. I think the docs may be wrong, as this other section implies db.shutdownServer is a clean way to shut down mongod: https://docs.mongodb.com/v3.2/reference/method/db.shutdownServer/

      "Shuts down the current mongod or mongos process cleanly and safely."

        1. mongod.conf
          0.8 kB

            Assignee:
            Kelsey Schubert
            Reporter:
            Fernando Ipar
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Created:
              Updated:
              Resolved: