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

Journal files not removed after clean shutdown

    XMLWordPrintableJSON

Details

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

    Description

      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."

      Attachments

        Activity

          People

            kelsey.schubert@mongodb.com Kelsey Schubert
            fipar Fernando Ipar
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: