[SERVER-15067] Unclean shutdown detected after clean shutdown with --nojournal Created: 28/Aug/14  Updated: 10/Dec/14  Resolved: 14/Nov/14

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

Type: Bug Priority: Major - P3
Reporter: Kevin Pulo Assignee: Kaloian Manassiev
Resolution: Cannot Reproduce Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Steps To Reproduce:

mlaunch --port 11111 --smallfiles --single --nojournal --binarypath /usr/local/m/versions/2.7.2/bin/
mongo --port 11111 admin --eval 'db.shutdownServer()'
mlaunch start

vs

mlaunch --port 11111 --smallfiles --single --nojournal --binarypath /usr/local/m/versions/2.7.3/bin/
mongo --port 11111 admin --eval 'db.shutdownServer()'
mlaunch start

Participants:

 Description   

Starting a mongod without journalling, then shutdown cleanly with db.shutdownServer(). Immediately restarting the mongod is expected to work, but it fails in 2.7.3 (works in 2.7.2). When --nojournal is omitted, restarting works as expected in both 2.7.2 and 2.7.3.

2.7.2 logs:

2014-08-28T12:08:56.640+1000 [initandlisten] MongoDB starting : pid=29395 port=11111 dbpath=/home/kev/t/data/db 64-bit host=genique
2014-08-28T12:08:56.640+1000 [initandlisten]
2014-08-28T12:08:56.640+1000 [initandlisten] ** NOTE: This is a development version (2.7.2) of MongoDB.
2014-08-28T12:08:56.640+1000 [initandlisten] **       Not recommended for production.
2014-08-28T12:08:56.640+1000 [initandlisten]
2014-08-28T12:08:56.640+1000 [initandlisten] db version v2.7.2
2014-08-28T12:08:56.640+1000 [initandlisten] git version: ce326e3ed8ae7f74c8c70deb225da56f678bb345
2014-08-28T12:08:56.640+1000 [initandlisten] build info: Linux build14.nj1.10gen.cc 2.6.32-431.3.1.el6.x86_64 #1 SMP Fri Jan 3 21:39:27 UTC 2014 x86_64 BOOST_LIB_VERSION=1_49
2014-08-28T12:08:56.640+1000 [initandlisten] allocator: tcmalloc
2014-08-28T12:08:56.640+1000 [initandlisten] options: { net: { port: 11111 }, processManagement: { fork: true }, storage: { dbPath: "/home/kev/t/data/db", journal: { enabled: false }, smallFiles: true }, systemLog: { destination: "file", logAppend: true, path: "/home/kev/t/data/mongod.log" } }
2014-08-28T12:08:56.654+1000 [FileAllocator] allocating new datafile /home/kev/t/data/db/local.ns, filling with zeroes...
2014-08-28T12:08:56.654+1000 [FileAllocator] creating directory /home/kev/t/data/db/_tmp
2014-08-28T12:08:56.667+1000 [FileAllocator] done allocating datafile /home/kev/t/data/db/local.ns, size: 16MB,  took 0.001 secs
2014-08-28T12:08:56.668+1000 [FileAllocator] allocating new datafile /home/kev/t/data/db/local.0, filling with zeroes...
2014-08-28T12:08:56.670+1000 [FileAllocator] done allocating datafile /home/kev/t/data/db/local.0, size: 16MB,  took 0.001 secs
2014-08-28T12:08:56.674+1000 [initandlisten] build index on: local.startup_log properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "local.startup_log" }
2014-08-28T12:08:56.674+1000 [initandlisten]     added index to empty collection
2014-08-28T12:08:56.674+1000 [initandlisten] waiting for connections on port 11111
2014-08-28T12:08:56.674+1000 [initandlisten] connection accepted from 127.0.0.1:48979 #1 (1 connection now open)
2014-08-28T12:08:56.677+1000 [initandlisten] connection accepted from 127.0.0.1:48980 #2 (2 connections now open)
2014-08-28T12:08:56.677+1000 [conn1] end connection 127.0.0.1:48979 (1 connection now open)
2014-08-28T12:08:56.678+1000 [conn2] end connection 127.0.0.1:48980 (0 connections now open)
2014-08-28T12:09:06.258+1000 [initandlisten] connection accepted from 127.0.0.1:48981 #3 (1 connection now open)
2014-08-28T12:09:06.266+1000 [conn3] terminating, shutdown command received
2014-08-28T12:09:06.266+1000 [conn3] dbexit: shutdown called
2014-08-28T12:09:06.266+1000 [conn3] shutdown: going to close listening sockets...
2014-08-28T12:09:06.266+1000 [conn3] closing listening socket: 7
2014-08-28T12:09:06.266+1000 [conn3] closing listening socket: 8
2014-08-28T12:09:06.266+1000 [conn3] removing socket file: /tmp/mongodb-11111.sock
2014-08-28T12:09:06.266+1000 [conn3] shutdown: going to flush diaglog...
2014-08-28T12:09:06.266+1000 [conn3] shutdown: going to close sockets...
2014-08-28T12:09:06.266+1000 [conn3] shutdown: waiting for fs preallocator...
2014-08-28T12:09:06.266+1000 [conn3] shutdown: closing all files...
2014-08-28T12:09:06.266+1000 [conn3] closeAllFiles() finished
2014-08-28T12:09:06.266+1000 [conn3] shutdown: removing fs lock...
2014-08-28T12:09:06.266+1000 [conn3] dbexit: really exiting now
2014-08-28T12:09:09.039+1000 ***** SERVER RESTARTED *****
2014-08-28T12:09:09.041+1000 [initandlisten] MongoDB starting : pid=29504 port=11111 dbpath=/home/kev/t/data/db 64-bit host=genique
2014-08-28T12:09:09.041+1000 [initandlisten]
2014-08-28T12:09:09.041+1000 [initandlisten] ** NOTE: This is a development version (2.7.2) of MongoDB.
2014-08-28T12:09:09.041+1000 [initandlisten] **       Not recommended for production.
2014-08-28T12:09:09.042+1000 [initandlisten]
2014-08-28T12:09:09.042+1000 [initandlisten] db version v2.7.2
2014-08-28T12:09:09.042+1000 [initandlisten] git version: ce326e3ed8ae7f74c8c70deb225da56f678bb345
2014-08-28T12:09:09.042+1000 [initandlisten] build info: Linux build14.nj1.10gen.cc 2.6.32-431.3.1.el6.x86_64 #1 SMP Fri Jan 3 21:39:27 UTC 2014 x86_64 BOOST_LIB_VERSION=1_49
2014-08-28T12:09:09.042+1000 [initandlisten] allocator: tcmalloc
2014-08-28T12:09:09.042+1000 [initandlisten] options: { net: { port: 11111 }, processManagement: { fork: true }, storage: { dbPath: "/home/kev/t/data/db", journal: { enabled: false }, smallFiles: true }, systemLog: { destination: "file", logAppend: true, path: "/home/kev/t/data/mongod.log" } }
2014-08-28T12:09:09.059+1000 [initandlisten] waiting for connections on port 11111
2014-08-28T12:09:09.059+1000 [initandlisten] connection accepted from 127.0.0.1:48983 #1 (1 connection now open)
2014-08-28T12:09:09.060+1000 [conn1] end connection 127.0.0.1:48983 (0 connections now open)
2014-08-28T12:09:09.065+1000 [initandlisten] connection accepted from 127.0.0.1:48984 #2 (1 connection now open)
2014-08-28T12:09:09.066+1000 [conn2] end connection 127.0.0.1:48984 (0 connections now open)
2014-08-28T12:09:09.067+1000 [initandlisten] connection accepted from 127.0.0.1:48985 #3 (1 connection now open)
2014-08-28T12:09:09.069+1000 [conn3] end connection 127.0.0.1:48985 (0 connections now open)

2.7.3 logs:

2014-08-28T12:09:59.225+1000 [initandlisten] MongoDB starting : pid=29861 port=11111 dbpath=/home/kev/t/data/db 64-bit host=genique
2014-08-28T12:09:59.225+1000 [initandlisten]
2014-08-28T12:09:59.225+1000 [initandlisten] ** NOTE: This is a development version (2.7.3) of MongoDB.
2014-08-28T12:09:59.225+1000 [initandlisten] **       Not recommended for production.
2014-08-28T12:09:59.226+1000 [initandlisten]
2014-08-28T12:09:59.226+1000 [initandlisten] db version v2.7.3
2014-08-28T12:09:59.226+1000 [initandlisten] git version: d4f9243fe8657876ffca838467f696aadad98414
2014-08-28T12:09:59.226+1000 [initandlisten] build info: Linux build11.nj1.10gen.cc 2.6.32-431.3.1.el6.x86_64 #1 SMP Fri Jan 3 21:39:27 UTC 2014 x86_64 BOOST_LIB_VERSION=1_49
2014-08-28T12:09:59.226+1000 [initandlisten] allocator: tcmalloc
2014-08-28T12:09:59.226+1000 [initandlisten] options: { net: { port: 11111 }, processManagement: { fork: true }, storage: { dbPath: "/home/kev/t/data/db", journal: { enabled: false }, smallFiles: true }, systemLog: { destination: "file", logAppend: true, path: "/home/kev/t/data/mongod.log" } }
2014-08-28T12:09:59.240+1000 [FileAllocator] allocating new datafile /home/kev/t/data/db/local.ns, filling with zeroes...
2014-08-28T12:09:59.240+1000 [FileAllocator] creating directory /home/kev/t/data/db/_tmp
2014-08-28T12:09:59.247+1000 [FileAllocator] done allocating datafile /home/kev/t/data/db/local.ns, size: 16MB,  took 0.001 secs
2014-08-28T12:09:59.250+1000 [FileAllocator] allocating new datafile /home/kev/t/data/db/local.0, filling with zeroes...
2014-08-28T12:09:59.252+1000 [FileAllocator] done allocating datafile /home/kev/t/data/db/local.0, size: 16MB,  took 0.001 secs
2014-08-28T12:09:59.254+1000 [initandlisten] build index on: local.startup_log properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "local.startup_log" }
2014-08-28T12:09:59.254+1000 [initandlisten]     added index to empty collection
2014-08-28T12:09:59.254+1000 [initandlisten] waiting for connections on port 11111
2014-08-28T12:09:59.254+1000 [initandlisten] connection accepted from 127.0.0.1:49008 #1 (1 connection now open)
2014-08-28T12:09:59.255+1000 [conn1] end connection 127.0.0.1:49008 (0 connections now open)
2014-08-28T12:09:59.255+1000 [initandlisten] connection accepted from 127.0.0.1:49009 #2 (1 connection now open)
2014-08-28T12:09:59.257+1000 [conn2] end connection 127.0.0.1:49009 (0 connections now open)
2014-08-28T12:10:02.212+1000 [initandlisten] connection accepted from 127.0.0.1:49010 #3 (1 connection now open)
2014-08-28T12:10:02.220+1000 [conn3] terminating, shutdown command received
2014-08-28T12:10:02.220+1000 [conn3] dbexit: shutdown called
2014-08-28T12:10:02.220+1000 [conn3] dbexit: really exiting now
2014-08-28T12:10:07.402+1000 ***** SERVER RESTARTED *****
2014-08-28T12:10:07.404+1000 [initandlisten] MongoDB starting : pid=29935 port=11111 dbpath=/home/kev/t/data/db 64-bit host=genique
2014-08-28T12:10:07.404+1000 [initandlisten]
2014-08-28T12:10:07.404+1000 [initandlisten] ** NOTE: This is a development version (2.7.3) of MongoDB.
2014-08-28T12:10:07.404+1000 [initandlisten] **       Not recommended for production.
2014-08-28T12:10:07.404+1000 [initandlisten]
2014-08-28T12:10:07.404+1000 [initandlisten] db version v2.7.3
2014-08-28T12:10:07.404+1000 [initandlisten] git version: d4f9243fe8657876ffca838467f696aadad98414
2014-08-28T12:10:07.404+1000 [initandlisten] build info: Linux build11.nj1.10gen.cc 2.6.32-431.3.1.el6.x86_64 #1 SMP Fri Jan 3 21:39:27 UTC 2014 x86_64 BOOST_LIB_VERSION=1_49
2014-08-28T12:10:07.404+1000 [initandlisten] allocator: tcmalloc
2014-08-28T12:10:07.404+1000 [initandlisten] options: { net: { port: 11111 }, processManagement: { fork: true }, storage: { dbPath: "/home/kev/t/data/db", journal: { enabled: false }, smallFiles: true }, systemLog: { destination: "file", logAppend: true, path: "/home/kev/t/data/mongod.log" } }
2014-08-28T12:10:07.404+1000 [initandlisten] exception in initAndListen: 12596 old lock file, terminating
2014-08-28T12:10:07.404+1000 [initandlisten] dbexit:
2014-08-28T12:10:07.405+1000 [initandlisten] dbexit: really exiting now



 Comments   
Comment by Kaloian Manassiev [ 14/Nov/14 ]

Hi Kevin,

I am unable to reproduce this issue as of 2.8 RC0. Quite a few changes went into the server since 2.7.3 and the problem might have been fixed.

I will resolve this issue. Fell free to reopen it if you are still seeing it.

-Kal.

Generated at Thu Feb 08 03:36:50 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.