[SERVER-20729] Database with WT fails to start after clean shutdown (missing WiredTiger.wt) Created: 01/Oct/15  Updated: 16/Nov/21  Resolved: 05/Oct/15

Status: Closed
Project: Core Server
Component/s: WiredTiger
Affects Version/s: 3.0.2, 3.0.3, 3.0.4
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Robert Pocklington Assignee: Unassigned
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Linux 3.13.0-65-generic #105-Ubuntu SMP Mon Sep 21 18:50:58 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux


Operating System: ALL
Steps To Reproduce:

1. Start mongodb with WT (sudo service mongod start)
2. Stop mongodb (sudo service mongod stop) - repeat 1,2 many times.
3. Logs will indicate issue and mongodb will fail to start.

Participants:

 Description   

This is not a file permission issue. Somehow after a clean shutdown the WiredTiger.wt file is missing and this means you cannot start mongodb again, effectively losing the database.

I have seen this a few times since using wired tiger, on 3.0.2 and currently on 3.0.4

This is out /etc/fstab for /data partition:
`/dev/xvdb /data xfs noatime 0 0`

Here is the mongodb log:

Oct  1 11:04:10 ip-172-31-0-19 mongod.27017[1127]: [conn20] build index done.  scanned 292 total records. 0 secs
Oct  1 11:04:10 ip-172-31-0-19 mongod.27017[1127]: [conn19] end connection 127.0.0.1:45601 (5 connections now open)
Oct  1 11:04:10 ip-172-31-0-19 mongod.27017[1127]: [conn21] end connection 127.0.0.1:45603 (5 connections now open)
Oct  1 11:04:10 ip-172-31-0-19 mongod.27017[1127]: [conn22] end connection 127.0.0.1:45604 (5 connections now open)
Oct  1 11:04:10 ip-172-31-0-19 mongod.27017[1127]: [conn20] end connection 127.0.0.1:45602 (2 connections now open)
Oct  1 11:04:39 ip-172-31-0-19 mongod.27017[1127]: [initandlisten] connection accepted from 127.0.0.1:45606 #23 (3 connections now open)
Oct  1 11:04:39 ip-172-31-0-19 mongod.27017[1127]: [conn23] end connection 127.0.0.1:45606 (2 connections now open)
Oct  1 16:00:04 alpha mongod.27017[1127]: [signalProcessingThread] got signal 15 (Terminated), will terminate after current cmd ends
Oct  1 16:00:04 alpha mongod.27017[1127]: [signalProcessingThread] now exiting
Oct  1 16:00:04 alpha mongod.27017[1127]: [signalProcessingThread] shutdown: going to close listening sockets...
Oct  1 16:00:04 alpha mongod.27017[1127]: [signalProcessingThread] closing listening socket: 5
Oct  1 16:00:04 alpha mongod.27017[1127]: [signalProcessingThread] closing listening socket: 6
Oct  1 16:00:04 alpha mongod.27017[1127]: [signalProcessingThread] removing socket file: /tmp/mongodb-27017.sock
Oct  1 16:00:04 alpha mongod.27017[1127]: [signalProcessingThread] shutdown: going to flush diaglog...
Oct  1 16:00:04 alpha mongod.27017[1127]: [signalProcessingThread] shutdown: going to close sockets...
Oct  1 16:00:04 alpha mongod.27017[1127]: [signalProcessingThread] WiredTigerKVEngine shutting down
Oct  1 16:00:04 alpha mongod.27017[1127]: [conn18] end connection 127.0.0.1:45239 (1 connection now open)
Oct  1 16:00:04 alpha mongod.27017[1127]: [conn17] end connection 127.0.0.1:45229 (1 connection now open)
Oct  1 16:00:04 alpha mongod.27017[1127]: [signalProcessingThread] shutdown: removing fs lock...
Oct  1 16:00:04 alpha mongod.27017[1127]: [signalProcessingThread] dbexit:  rc: 0
Oct  1 20:00:44 alpha mongod.27017[1074]: [initandlisten] wiredtiger_open config: create,cache_size=8G,session_max=20000,eviction=(threads_max=4),statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0),
Oct  1 20:00:44 alpha mongod.27017[1074]: [initandlisten] WiredTiger (2) [1443729644:306783][1074:0x7fdba8fd4bc0], file:WiredTiger.wt, connection: /data/db/WiredTiger.wt: No such file or directory
Oct  1 20:00:44 alpha mongod.27017[1074]: [initandlisten] Assertion: 28595:2: No such file or directory
Oct  1 20:00:44 alpha mongod.27017[1074]: [initandlisten] exception in initAndListen: 28595 2: No such file or directory, terminating
Oct  1 20:00:44 alpha mongod.27017[1074]: [initandlisten] dbexit:  rc: 100



 Comments   
Comment by Ramon Fernandez Marina [ 06/Oct/16 ]

guy.margalit@noobaa.com, this error message:

./metadata_storage/WiredTiger.wt: handle-open: open: No such file or directory

doesn't indicate a bug, but a problem in your installation: the WiredTiger.wt file is missing! As I wrote above, altering the contents of dbpath on a running system may lead to undefined behavior and is not a supported configuration. Same goes for any manual modification of WiredTiger files in any way.

Please note that the SERVER project is for reporting bugs or feature suggestions for the MongoDB server. For MongoDB-related support discussion please post on the mongodb-user group or Stack Overflow with the mongodb tag, where your question will reach a larger audience.

Thanks,
Ramón.

Comment by Guy Margalit [ 06/Oct/16 ]

Still happens on Mac with mongodb v3.2.9.
Reopen?

2016-10-06T09:55:06.086+0300 I CONTROL  [initandlisten] MongoDB starting : pid=2839 port=27017 dbpath=./metadata_storage 64-bit host=local
2016-10-06T09:55:06.087+0300 I CONTROL  [initandlisten] db version v3.2.9
2016-10-06T09:55:06.087+0300 I CONTROL  [initandlisten] git version: 22ec9e93b40c85fc7cae7d56e7d6a02fd811088c
2016-10-06T09:55:06.087+0300 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.0.2j  26 Sep 2016
2016-10-06T09:55:06.087+0300 I CONTROL  [initandlisten] allocator: system
2016-10-06T09:55:06.087+0300 I CONTROL  [initandlisten] modules: none
2016-10-06T09:55:06.087+0300 I CONTROL  [initandlisten] build environment:
2016-10-06T09:55:06.087+0300 I CONTROL  [initandlisten]     distarch: x86_64
2016-10-06T09:55:06.087+0300 I CONTROL  [initandlisten]     target_arch: x86_64
2016-10-06T09:55:06.087+0300 I CONTROL  [initandlisten] options: { config: "mongod.conf", net: { bindIp: "127.0.0.1" }, storage: { dbPath: "./metadata_storage", engine: "wiredTiger" } }
2016-10-06T09:55:06.088+0300 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=9G,session_max=20000,eviction=(threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0),
2016-10-06T09:55:06.090+0300 E STORAGE  [initandlisten] WiredTiger (2) [1475736906:90729][2839:0x7fff76cfe000], file:WiredTiger.wt, connection: ./metadata_storage/WiredTiger.wt: handle-open: open: No such file or directory
2016-10-06T09:55:06.098+0300 I -        [initandlisten] Assertion: 28595:2: No such file or directory
2016-10-06T09:55:06.099+0300 I STORAGE  [initandlisten] exception in initAndListen: 28595 2: No such file or directory, terminating
2016-10-06T09:55:06.099+0300 I CONTROL  [initandlisten] dbexit:  rc: 100

Comment by Ramon Fernandez Marina [ 05/Oct/15 ]

Thanks for the update rpocklin. Please note that altering the contents of dbpath on a running system may lead to undefined behavior and is not a supported configuration. Same goes for any manual modification of WiredTiger files in any way.

Also the SERVER project is for reporting bugs or feature suggestions for the MongoDB server. For MongoDB-related support discussion please post on the mongodb-user group or Stack Overflow with the mongodb tag, where your question will reach a larger audience. See also our Technical Support page for additional support resources.

Regards,
Ramón.

Comment by Robert Pocklington [ 05/Oct/15 ]

Solved - before running 'mongorestore' we were deleting all files in '/data/db' and '/data/db/journal' explicitly. Mongorestore would work but seems the DB is in an inconsistent state if you try and restart.

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