[SERVER-12989] journal file cleanup failure post mongod termination with ctrl-c on windows 8 Created: 02/Mar/14  Updated: 10/Dec/14  Resolved: 10/Jun/14

Status: Closed
Project: Core Server
Component/s: Storage
Affects Version/s: 2.6.0-rc0
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Shailesh Tak Assignee: Mark Benvenuto
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:

run mongod
ctrl-c

Participants:

 Description   

looks like journal and lock files are not getting cleaned post ctrl-c on mongod in windows.

c:\Programs\MongoDB\2.6.0-rc0\bin>mongod --dbpath C:\Programs\MongoDB\2.6.0-rc0\data --port 27017 --cpu --quiet
2014-03-02T15:17:51.971-0500 [initandlisten] MongoDB starting : pid=4976 port=27017 dbpath=C:\Programs\MongoDB\2.6.0-rc0\data 64-bit host=TAKFAMILYPC
2014-03-02T15:17:51.987-0500 [initandlisten] targetMinOS: Windows 7/Windows Server 2008 R2
2014-03-02T15:17:51.987-0500 [initandlisten] db version v2.6.0-rc0
2014-03-02T15:17:51.987-0500 [initandlisten] git version: 3779bf419438d2625277cf3c1c7216c497f683a8
2014-03-02T15:17:51.987-0500 [initandlisten] build info: windows sys.getwindowsversion(major=6, minor=1, build=7601, platform=2, service_pack='Service
Pack 1') BOOST_LIB_VERSION=1_49
2014-03-02T15:17:51.987-0500 [initandlisten] allocator: system
2014-03-02T15:17:52.002-0500 [initandlisten] options: { cpu: true, net:

{ port: 27017 }

, storage:

{ dbPath: "C:\Programs\MongoDB\2.6.0-rc0\data" }

, sy
stemLog:

{ quiet: true }

}
2014-03-02T15:17:52.034-0500 [initandlisten] journal dir=C:\Programs\MongoDB\2.6.0-rc0\data\journal
2014-03-02T15:17:52.034-0500 [initandlisten] recover : no journal files present, no recovery needed
2014-03-02T15:17:52.159-0500 [initandlisten] waiting for connections on port 27017
2014-03-02T15:17:56.175-0500 [snapshotthread] cpu: elapsed:4007 writelock: 0%
2014-03-02T15:18:00.191-0500 [snapshotthread] cpu: elapsed:4016 writelock: 0%
2014-03-02T15:18:04.207-0500 [snapshotthread] cpu: elapsed:4016 writelock: 0%
2014-03-02T15:18:08.207-0500 [snapshotthread] cpu: elapsed:4000 writelock: 303%
2014-03-02T15:18:12.223-0500 [snapshotthread] cpu: elapsed:4016 writelock: -2147483648%
2014-03-02T15:18:16.224-0500 [snapshotthread] cpu: elapsed:4000 writelock: 0%
2014-03-02T15:18:20.240-0500 [snapshotthread] cpu: elapsed:4016 writelock: 0%
2014-03-02T15:18:24.256-0500 [snapshotthread] cpu: elapsed:4016 writelock: 0%
2014-03-02T15:18:28.272-0500 [snapshotthread] cpu: elapsed:4015 writelock: 0%
2014-03-02T15:18:32.273-0500 [snapshotthread] cpu: elapsed:4000 writelock: 0%
2014-03-02T15:18:36.289-0500 [snapshotthread] cpu: elapsed:4016 writelock: 0%
Ctrl-C signal2014-03-02T15:18:38.820-0500 [consoleTerminate] got CTRL_C_EVENT, will terminate after current cmd ends
2014-03-02T15:18:38.820-0500 [consoleTerminate] now exiting
dbexit: 2014-03-02T15:18:38.820-0500 [consoleTerminate] shutdown: going to close listening sockets...
2014-03-02T15:18:38.820-0500 [consoleTerminate] closing listening socket: 476
2014-03-02T15:18:38.836-0500 [consoleTerminate] shutdown: going to flush diaglog...
2014-03-02T15:18:38.836-0500 [consoleTerminate] shutdown: going to close sockets...
2014-03-02T15:18:38.836-0500 [consoleTerminate] shutdown: waiting for fs preallocator...
2014-03-02T15:18:38.836-0500 [consoleTerminate] shutdown: lock for final commit...
2014-03-02T15:18:38.836-0500 [consoleTerminate] shutdown: final commit...
2014-03-02T15:18:38.898-0500 [consoleTerminate] shutdown: closing all files...
2014-03-02T15:18:38.898-0500 [consoleTerminate] closeAllFiles() finished
2014-03-02T15:18:38.898-0500 [consoleTerminate] journalCleanup...
2014-03-02T15:18:38.914-0500 [consoleTerminate] removeJournalFiles
2014-03-02T15:18:38.914-0500 [consoleTerminate] Assertion failure !haveJournalFiles() src\mongo\db\dur_journal.cpp 258
2014-03-02T15:18:39.398-0500 [consoleTerminate] mongod.exe ...\src\mongo\util\stacktrace.cpp(169) mongo::printStackTrace+0x43
2014-03-02T15:18:39.398-0500 [consoleTerminate] mongod.exe ...\src\mongo\util\log.cpp(158) mongo::logContext+0x9c
2014-03-02T15:18:39.398-0500 [consoleTerminate] mongod.exe ...\src\mongo\util\assert_util.cpp(115) mongo::verifyFailed+0x14a
2014-03-02T15:18:39.398-0500 [consoleTerminate] mongod.exe ...\src\mongo\db\dur_journal.cpp(258) mongo::dur::removeJournalFiles+0x3b0
2014-03-02T15:18:39.398-0500 [consoleTerminate] mongod.exe ...\src\mongo\db\dur_journal.cpp(276) mongo::dur::Journal::cleanup+0xab
2014-03-02T15:18:39.398-0500 [consoleTerminate] mongod.exe ...\src\mongo\db\instance.cpp(1107) mongo::shutdownServer+0x5f1
2014-03-02T15:18:39.414-0500 [consoleTerminate] mongod.exe ...\src\mongo\db\instance.cpp(1167) mongo::dbexit+0x3ea
2014-03-02T15:18:39.414-0500 [consoleTerminate] mongod.exe ...\src\mongo\db\instance.cpp(1134) mongo::exitCleanly+0xb8
2014-03-02T15:18:39.414-0500 [consoleTerminate] mongod.exe ...\src\mongo\db\db.cpp(1126) mongo::consoleTerminate+0xc1
2014-03-02T15:18:39.414-0500 [consoleTerminate] mongod.exe ...\src\mongo\db\db.cpp(1135) mongo::CtrlHandler+0xee
2014-03-02T15:18:39.414-0500 [consoleTerminate] KERNELBASE.dll CtrlRoutine+0xa3
2014-03-02T15:18:39.430-0500 [consoleTerminate] KERNEL32.DLL BaseThreadInitThunk+0xd
2014-03-02T15:18:39.430-0500 [consoleTerminate]
2014-03-02T15:18:39.430-0500 [consoleTerminate] error couldn't remove journal file during shutdown assertion src\mongo\db\dur_journal.cpp:258
shutdown failed with exceptiondbexit: really exiting now



 Comments   
Comment by Ramon Fernandez Marina [ 10/Jun/14 ]

Hi shaileshtak,

we haven't heard back from you for some time, so I'm going to mark this issue as resolved. If this is still an issue for you, please feel free to re-open the ticket and answer Mark's question above (dir /s ...) to help us reproduce the problem.

Regards,
Ramón.

Comment by Thomas Rueckstiess [ 16/Apr/14 ]

Hi Shailesh,

Just checking in to see if you can run the additional "dir" after the repro fails, as that would help us with the diagnosis of the issue. If you can share any additional information that might potentially be helpful to reproduce, that would be great also.

Thanks,
Thomas

Comment by Mark Benvenuto [ 04/Mar/14 ]

I tried on a different machine today (first machine was SSD based, and not virtual, new machine was EC2 based virtual machine) to try to repro the problem. I still cannot repro it.

When it fails, can you run
dir /s C:\Programs\MongoDB\2.6.0-rc0\data\journal

to see what files remain after it fails, and post this to the bug.

Comment by Shailesh Tak [ 04/Mar/14 ]

Mark,
I think it's timing, I was able to reproduce is today couple times (3-4
times out of 30-35).
mongod.lock file was left behind.

My Windows version details.
c:\Programs\MongoDB\2.6.0-rc0\bin>ver
Microsoft Windows [Version 6.3.9600]

I will keep trying to see if I can give you repeatable test case, as it
will help you with resolution.

Here is the output from windows I initiated mongod.
c:\Programs\MongoDB\2.6.0-rc0\bin>mongod --dbpath
C:\Programs\MongoDB\2.6.0-rc0\data --port 27017 --cpu
2014-03-03T20:31:59.256-0500 [initandlisten] MongoDB starting : pid=21880
port=27017 dbpath=C:\Programs\MongoDB\2.6.0-rc0\data 64-bit host=TAKFAMILYPC
2014-03-03T20:31:59.256-0500 [initandlisten] targetMinOS: Windows 7/Windows
Server 2008 R2
2014-03-03T20:31:59.256-0500 [initandlisten] db version v2.6.0-rc0
2014-03-03T20:31:59.256-0500 [initandlisten] git version:
3779bf419438d2625277cf3c1c7216c497f683a8
2014-03-03T20:31:59.272-0500 [initandlisten] build info: windows
sys.getwindowsversion(major=6, minor=1, build=7601, platform=2,
service_pack='Service
Pack 1') BOOST_LIB_VERSION=1_49
2014-03-03T20:31:59.272-0500 [initandlisten] allocator: system
2014-03-03T20:31:59.272-0500 [initandlisten] options: { cpu: true, net:

{ port: 27017 }

, storage:

{ dbPath: "C:\Programs\MongoDB\2.6.0-rc0\data" }

}
2014-03-03T20:31:59.303-0500 [initandlisten] journal
dir=C:\Programs\MongoDB\2.6.0-rc0\data\journal
2014-03-03T20:31:59.303-0500 [initandlisten] recover : no journal files
present, no recovery needed
2014-03-03T20:31:59.475-0500 [initandlisten] waiting for connections on
port 27017
*2014-03-03T20:32:03.491-0500 [snapshotthread] cpu: elapsed:4013
writelock: 0%*
Ctrl-C signal2014-03-03T20:32:07.117-0500 [consoleTerminate] got
CTRL_C_EVENT, will terminate after current cmd ends
2014-03-03T20:32:07.117-0500 [consoleTerminate] now exiting
dbexit: 2014-03-03T20:32:07.117-0500 [consoleTerminate] shutdown: going to
close listening sockets...
2014-03-03T20:32:07.117-0500 [consoleTerminate] closing listening socket:
476
2014-03-03T20:32:07.117-0500 [consoleTerminate] shutdown: going to flush
diaglog...
2014-03-03T20:32:07.117-0500 [consoleTerminate] shutdown: going to close
sockets...
2014-03-03T20:32:07.132-0500 [consoleTerminate] shutdown: waiting for fs
preallocator...
2014-03-03T20:32:07.132-0500 [consoleTerminate] shutdown: lock for final
commit...
2014-03-03T20:32:07.132-0500 [consoleTerminate] shutdown: final commit...
2014-03-03T20:32:07.195-0500 [consoleTerminate] shutdown: closing all
files...
2014-03-03T20:32:07.210-0500 [consoleTerminate] closeAllFiles() finished
2014-03-03T20:32:07.210-0500 [consoleTerminate] journalCleanup...
2014-03-03T20:32:07.210-0500 [consoleTerminate] removeJournalFiles
2014-03-03T20:32:07.226-0500 [consoleTerminate] Assertion failure
!haveJournalFiles() src\mongo\db\dur_journal.cpp 258
2014-03-03T20:32:07.742-0500 [consoleTerminate] mongod.exe
...\src\mongo\util\stacktrace.cpp(169) mongo::printStackTrace+0x43
2014-03-03T20:32:07.742-0500 [consoleTerminate] mongod.exe
...\src\mongo\util\log.cpp(158) mongo::logContext+0x9c
2014-03-03T20:32:07.742-0500 [consoleTerminate] mongod.exe
...\src\mongo\util\assert_util.cpp(115) mongo::verifyFailed+0x14a
2014-03-03T20:32:07.742-0500 [consoleTerminate] mongod.exe
...\src\mongo\db\dur_journal.cpp(258)
mongo::dur::removeJournalFiles+0x3b0
2014-03-03T20:32:07.742-0500 [consoleTerminate] mongod.exe
...\src\mongo\db\dur_journal.cpp(276) mongo::dur::Journal::cleanup+0xab
2014-03-03T20:32:07.742-0500 [consoleTerminate] mongod.exe
...\src\mongo\db\instance.cpp(1107) mongo::shutdownServer+0x5f1
2014-03-03T20:32:07.757-0500 [consoleTerminate] mongod.exe
...\src\mongo\db\instance.cpp(1167) mongo::dbexit+0x3ea
2014-03-03T20:32:07.757-0500 [consoleTerminate] mongod.exe
...\src\mongo\db\instance.cpp(1134) mongo::exitCleanly+0xb8
2014-03-03T20:32:07.757-0500 [consoleTerminate] mongod.exe
...\src\mongo\db\db.cpp(1126) mongo::consoleTerminate+0xc1
2014-03-03T20:32:07.757-0500 [consoleTerminate] mongod.exe
...\src\mongo\db\db.cpp(1135) mongo::CtrlHandler+0xee
2014-03-03T20:32:07.773-0500 [consoleTerminate]
KERNELBASE.dll CtrlRoutine+0xa3
2014-03-03T20:32:07.773-0500 [consoleTerminate]
KERNEL32.DLL
BaseThreadInitThunk+0xd
2014-03-03T20:32:07.773-0500 [consoleTerminate]
2014-03-03T20:32:07.773-0500 [consoleTerminate] error couldn't remove
journal file during shutdown assertion src\mongo\db\dur_journal.cpp:258
shutdown failed with exceptiondbexit: really exiting now

Regards
Shailesh

'Peace and Joy on the Universe'

Comment by Mark Benvenuto [ 03/Mar/14 ]

I cannot reproduce this bug. I wrote a script to start mongod, and hit control-C on mongod after a random sleep 60 times without hitting an assert.

What file was left behind?

Also, it appears you are running on Windows 7 according to this version number instead of Windows 8.

2014-03-02T15:17:51.987-0500 [initandlisten] build info: windows sys.getwindowsversion(major=6, minor=1, build=7601, platform=2, service_pack='Service
Pack 1') BOOST_LIB_VERSION=1_49

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