[SERVER-27272] MongoDB 3.4 fails on service restart Created: 04/Dec/16  Updated: 30/Jan/17  Resolved: 30/Jan/17

Status: Closed
Project: Core Server
Component/s: WiredTiger
Affects Version/s: 3.4.0-rc0, 3.4.0-rc1, 3.4.0-rc2, 3.4.0-rc3, 3.4.0-rc4, 3.4.0-rc5, 3.4.0
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Rostyslav Mykhajliw Assignee: Unassigned
Resolution: Incomplete Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Steps To Reproduce:

1. setup a new instance
2. start mongo
3. stop mongo
4. reboot host

Installation receipt:
```
run "sudo apt-key adv --keyserver hkp://keyserver.ubuntu.com:80 --recv 0C49F3730359A14518585931BC711F9BA15703C6"
run "echo \"deb http://repo.mongodb.org/apt/ubuntu xenial/mongodb-org/3.4 multiverse\" | sudo tee /etc/apt/sources.list.d/mongodb-org-3.4.list"

run "sudo apt-get update"
run "sudo apt-get install -y --allow-unauthenticated mongodb-org"

run "sudo service mongod stop || true"

tmpfile = "/tmp/mongodb.conf"
put IO.read("config/deploy/plugin/mongo/mongod.conf"), tmpfile
run "sudo mv #

{tmpfile} /etc/mongod.conf"

tmpfile = "/tmp/mongodb.service"
put IO.read("config/deploy/plugin/mongo/systemd/mongodb.service"), tmpfile
run "sudo mv #{tmpfile}

/etc/systemd/system/mongodb.service"

run "sudo systemctl daemon-reload"
run "sudo systemctl enable mongodb.service"

run "sudo systemctl start mongodb || true"
```
commands after install

  1. sudo systemctl stop mongodb
  2. sudo reboot
Participants:

 Description   

I've setup mongo 3.4 on m4.large instance but it fails even just after service stop and system reboot

  1. sudo systemctl stop mongodb
  2. sudo reboot

Logs

2016-12-04T19:29:45.241+0000 I CONTROL  [initandlisten] MongoDB starting : pid=28930 port=27017 dbpath=/var/lib/mongodb 64-bit host=ip-172-30-1-203.us-west-2.compute.internal
2016-12-04T19:29:45.241+0000 I CONTROL  [initandlisten] db version v3.4.0
2016-12-04T19:29:45.241+0000 I CONTROL  [initandlisten] git version: f4240c60f005be757399042dc12f6addbc3170c1
2016-12-04T19:29:45.241+0000 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.0.2g  1 Mar 2016
2016-12-04T19:29:45.241+0000 I CONTROL  [initandlisten] allocator: tcmalloc
2016-12-04T19:29:45.241+0000 I CONTROL  [initandlisten] modules: none
2016-12-04T19:29:45.241+0000 I CONTROL  [initandlisten] build environment:
2016-12-04T19:29:45.241+0000 I CONTROL  [initandlisten]     distmod: ubuntu1604
2016-12-04T19:29:45.241+0000 I CONTROL  [initandlisten]     distarch: x86_64
2016-12-04T19:29:45.241+0000 I CONTROL  [initandlisten]     target_arch: x86_64
2016-12-04T19:29:45.241+0000 I CONTROL  [initandlisten] options: { config: "/etc/mongod.conf", net: { bindIp: "0.0.0.0", port: 27017 }, replication: { replSetName: "tt" }, storage: { dbPath: "/var/lib/mongodb", engine: "wiredTiger", journal: { enabled: false } }, systemLog: { destination: "file", logAppend: true, path: "/var/log/mongodb/mongod.log", quiet: true } }
2016-12-04T19:29:45.269+0000 I STORAGE  [initandlisten]
2016-12-04T19:29:45.269+0000 I STORAGE  [initandlisten] ** WARNING: Using the XFS filesystem is strongly recommended with the WiredTiger storage engine
2016-12-04T19:29:45.269+0000 I STORAGE  [initandlisten] See http://dochub.mongodb.org/core/prodnotes-filesystem
2016-12-04T19:29:45.269+0000 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=3478M,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),,log=(enabled=false),
2016-12-04T19:29:45.341+0000 I CONTROL  [initandlisten]
2016-12-04T19:29:45.341+0000 I CONTROL  [initandlisten] ** WARNING: Access control is not enabled for the database.
2016-12-04T19:29:45.341+0000 I CONTROL  [initandlisten] **          Read and write access to data and configuration is unrestricted.
2016-12-04T19:29:45.341+0000 I CONTROL  [initandlisten]
2016-12-04T19:29:45.360+0000 I FTDC     [initandlisten] Initializing full-time diagnostic data capture with directory '/var/lib/mongodb/diagnostic.data'
2016-12-04T19:29:45.385+0000 I REPL     [initandlisten] Did not find local voted for document at startup;  NoMatchingDocument: Did not find replica set lastVote document in local.replset.election
2016-12-04T19:29:45.385+0000 I REPL     [initandlisten] Did not find local replica set configuration document at startup;  NoMatchingDocument: Did not find replica set configuration document in local.system.replset
2016-12-04T19:29:45.385+0000 I NETWORK  [thread1] waiting for connections on port 27017
2016-12-04T19:40:12.723+0000 I CONTROL  [signalProcessingThread] got signal 15 (Terminated), will terminate after current cmd ends
2016-12-04T19:40:12.723+0000 I NETWORK  [signalProcessingThread] shutdown: going to close listening sockets...
2016-12-04T19:40:12.723+0000 I NETWORK  [signalProcessingThread] closing listening socket: 7
2016-12-04T19:40:12.723+0000 I NETWORK  [signalProcessingThread] closing listening socket: 8
2016-12-04T19:40:12.723+0000 I NETWORK  [signalProcessingThread] removing socket file: /tmp/mongodb-27017.sock
2016-12-04T19:40:12.723+0000 I NETWORK  [signalProcessingThread] shutdown: going to flush diaglog...
2016-12-04T19:40:12.723+0000 I REPL     [signalProcessingThread] shutting down replication subsystems
2016-12-04T19:40:12.723+0000 I FTDC     [signalProcessingThread] Shutting down full-time diagnostic data capture
2016-12-04T19:40:12.724+0000 I STORAGE  [signalProcessingThread] WiredTigerKVEngine shutting down
2016-12-04T19:40:12.734+0000 I STORAGE  [signalProcessingThread] shutdown: removing fs lock...
2016-12-04T19:40:12.735+0000 I CONTROL  [signalProcessingThread] now exiting
2016-12-04T19:40:12.735+0000 I CONTROL  [signalProcessingThread] shutting down with code:0
2016-12-04T19:40:12.735+0000 I CONTROL  [initandlisten] shutting down with code:0
2016-12-04T19:41:21.025+0000 I CONTROL  [main] ***** SERVER RESTARTED *****
2016-12-04T19:41:21.099+0000 I CONTROL  [initandlisten] MongoDB starting : pid=1716 port=27017 dbpath=/var/lib/mongodb 64-bit host=ip-172-30-1-203.us-west-2.compute.internal
2016-12-04T19:41:21.099+0000 I CONTROL  [initandlisten] db version v3.4.0
2016-12-04T19:41:21.099+0000 I CONTROL  [initandlisten] git version: f4240c60f005be757399042dc12f6addbc3170c1
2016-12-04T19:41:21.099+0000 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.0.2g  1 Mar 2016
2016-12-04T19:41:21.099+0000 I CONTROL  [initandlisten] allocator: tcmalloc
2016-12-04T19:41:21.099+0000 I CONTROL  [initandlisten] modules: none
2016-12-04T19:41:21.099+0000 I CONTROL  [initandlisten] build environment:
2016-12-04T19:41:21.099+0000 I CONTROL  [initandlisten]     distmod: ubuntu1604
2016-12-04T19:41:21.099+0000 I CONTROL  [initandlisten]     distarch: x86_64
2016-12-04T19:41:21.099+0000 I CONTROL  [initandlisten]     target_arch: x86_64
2016-12-04T19:41:21.099+0000 I CONTROL  [initandlisten] options: { config: "/etc/mongod.conf", net: { bindIp: "0.0.0.0", port: 27017 }, replication: { replSetName: "tt" }, storage: { dbPath: "/var/lib/mongodb", engine: "wiredTiger", journal: { enabled: false } }, systemLog: { destination: "file", logAppend: true, path: "/var/log/mongodb/mongod.log", quiet: true } }
2016-12-04T19:41:21.108+0000 W -        [initandlisten] Detected unclean shutdown - /var/lib/mongodb/mongod.lock is not empty.
2016-12-04T19:41:21.196+0000 W STORAGE  [initandlisten] Recovering data from the last clean checkpoint.
2016-12-04T19:41:21.196+0000 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=3478M,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),,log=(enabled=false),
2016-12-04T19:41:21.365+0000 E STORAGE  [initandlisten] WiredTiger error (-31802) [1480880481:365973][1716:0x7fbab4eed100], file:WiredTiger.wt, connection: unable to read root page from file:WiredTiger.wt: WT_ERROR: non-specific WiredTiger error
2016-12-04T19:41:21.366+0000 E STORAGE  [initandlisten] WiredTiger error (0) [1480880481:366016][1716:0x7fbab4eed100], file:WiredTiger.wt, connection: WiredTiger has failed to open its metadata
2016-12-04T19:41:21.366+0000 E STORAGE  [initandlisten] WiredTiger error (0) [1480880481:366025][1716:0x7fbab4eed100], file:WiredTiger.wt, connection: This may be due to the database files being encrypted, being from an older version or due to corruption on disk
2016-12-04T19:41:21.366+0000 E STORAGE  [initandlisten] WiredTiger error (0) [1480880481:366032][1716:0x7fbab4eed100], file:WiredTiger.wt, connection: You should confirm that you have opened the database with the correct options including all encryption and compression options
2016-12-04T19:41:21.394+0000 I -        [initandlisten] Assertion: 28595:-31802: WT_ERROR: non-specific WiredTiger error src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp 267
2016-12-04T19:41:21.558+0000 I STORAGE  [initandlisten] exception in initAndListen: 28595 -31802: WT_ERROR: non-specific WiredTiger error, terminating
2016-12-04T19:41:21.558+0000 I NETWORK  [initandlisten] shutdown: going to close listening sockets...
2016-12-04T19:41:21.558+0000 I NETWORK  [initandlisten] removing socket file: /tmp/mongodb-27017.sock
2016-12-04T19:41:21.558+0000 I NETWORK  [initandlisten] shutdown: going to flush diaglog...
2016-12-04T19:41:21.558+0000 I CONTROL  [initandlisten] now exiting
2016-12-04T19:41:21.558+0000 I CONTROL  [initandlisten] shutting down with code:100

That's a really scary behavior, I've got the same issue with dta or without data, on clean aws instance. It fails and cant restore.
MongoDb 3.2 with WiredTiger works well in the same environment.



 Comments   
Comment by Kelsey Schubert [ 30/Jan/17 ]

Hi necromant2005@gmail.com,

We haven’t heard back from you for some time, so I’m going to mark this ticket as resolved. If this is still an issue for you, please provide additional information and we will reopen the ticket.

Regards,
Thomas

Comment by Kelsey Schubert [ 06/Jan/17 ]

Hi necromant2005@gmail.com,

We still need additional information to diagnose the problem. If this is still an issue for you, would you please provide the information Bruce requested?

Thank you,
Thomas

Comment by Bruce Lucas (Inactive) [ 05/Dec/16 ]

Hi Rostyslav,

In addition to the db files as requested by my colleagues, can you please provide the following in order to help us rule out some system and other issues:

  • Attach a copy of the mongodb.service file to help us rule out configuration issues.
  • Attach or post the output of ls -lR /var/lib/mongodb, both just before and just after rebooting to help us rule out issues such as userids or permissions.
  • Attach both the /var/log/syslog and mongodb.log files to this ticket after rebooting to help us rule out system issues.
  • Attach or post the output of the mount command to help us rule out issues related to the disk.

Thanks,
Bruce

Comment by Rostyslav Mykhajliw [ 05/Dec/16 ]

Hi Thomas,

1. A new 3.4 DB, just installed
2. https://www.dropbox.com/s/slpulu58lfkmb5f/mongod.conf?dl=0
3. I've dropped it, but I can reproduce it.

Cheers,

Comment by Kelsey Schubert [ 04/Dec/16 ]

Hi necromant2005@gmail.com,

I've created a secure upload portal for you to use to provide the requested files. Files uploaded to this portal are only visible to MongoDB employees investigating this issue and are routinely deleted after some time.

Thanks for your help,
Thomas

Comment by Alexander Gorrod [ 04/Dec/16 ]

necromant2005@gmail.com We are sorry you are having trouble with MongoDB. Could you please provide the following information:

  • Was the database first created with MongoDB 3.4, or is it an upgrade from an earlier version of MongoDB?
  • Could you please upload the mongodb.conf file referenced in your script.
  • Could you upload all content in the database directory
Generated at Thu Feb 08 04:14:42 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.