[SERVER-24106] Journal files not removed after clean shutdown Created: 09/May/16  Updated: 17/May/16  Resolved: 16/May/16

Status: Closed
Project: Core Server
Component/s: Storage
Affects Version/s: 3.2.6
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Fernando Ipar Assignee: Kelsey Schubert
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File mongod.conf    
Issue Links:
Related
is related to DOCS-7847 Clarify WiredTiger journal files are ... Closed
Operating System: ALL
Steps To Reproduce:

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

Participants:

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



 Comments   
Comment by Fernando Ipar [ 16/May/16 ]

Hello Thomas,

Thanks, I've voted on DOCS-7847 as re reading this page after, without your explanation, it would not be clear to me that the behavior of removing journal files on a clean shutdown applies only to MMAPv1.

Regards,
Fernando.

Comment by Kelsey Schubert [ 16/May/16 ]

Hi fipar,

Thank you for reporting this behavior. The documentation you reference is specific to MMAPv1, and does not describe how WiredTiger handles journal files on shutdown. The section on journaling in WiredTiger is just above on the same page. I have opened DOCS-7847 to clarify this difference between journaling in MMAPv1 and WiredTiger in our documentation. Please review my explanation in DOCS-7847 and feel free to vote for it and watch it for updates.

Kind regards,
Thomas

Comment by Fernando Ipar [ 09/May/16 ]

I can see the formatting was broken when printing the config file, so here it is attached.

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