[SERVER-43127] Unable to start mongodb Created: 02/Sep/19  Updated: 10/Oct/19  Resolved: 10/Oct/19

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

Type: Bug Priority: Major - P3
Reporter: Douwe de Vries Assignee: Carl Champain (Inactive)
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Participants:

 Description   

This morning my mongodb was not working so I ran a status:

 

root@score:/var/lib/mongodb# systemctl status mongodb
● mongodb.service - High-performance, schema-free document-oriented database
   Loaded: loaded (/etc/systemd/system/mongodb.service; enabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Mon 2019-09-02 10:19:08 CEST; 5s ago
  Process: 1217 ExecStart=/usr/bin/mongod --quiet --config /etc/mongod.conf (code=exited, status=100)
 Main PID: 1217 (code=exited, status=100)
 
 
Sep 02 10:19:07 score.real-tech.nl systemd[1]: Started High-performance, schema-free document-oriented database.
Sep 02 10:19:08 score.real-tech.nl systemd[1]: mongodb.service: Main process exited, code=exited, status=100/n/a
Sep 02 10:19:08 score.real-tech.nl systemd[1]: mongodb.service: Failed with result 'exit-code'.

To get some more info I just tried to run `mongod`:

 

2019-09-02T10:24:01.510+0200 I CONTROL  [initandlisten] MongoDB starting : pid=1288 port=27017 dbpath=/data/db 64-bit host=score.real-tech.nl
2019-09-02T10:24:01.510+0200 I CONTROL  [initandlisten] db version v3.6.3
2019-09-02T10:24:01.510+0200 I CONTROL  [initandlisten] git version: 9586e557d54ef70f9ca4b43c26892cd55257e1a5
2019-09-02T10:24:01.510+0200 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.1.1  11 Sep 2018
2019-09-02T10:24:01.510+0200 I CONTROL  [initandlisten] allocator: tcmalloc
2019-09-02T10:24:01.510+0200 I CONTROL  [initandlisten] modules: none
2019-09-02T10:24:01.510+0200 I CONTROL  [initandlisten] build environment:
2019-09-02T10:24:01.511+0200 I CONTROL  [initandlisten]     distarch: x86_64
2019-09-02T10:24:01.511+0200 I CONTROL  [initandlisten]     target_arch: x86_64
2019-09-02T10:24:01.511+0200 I CONTROL  [initandlisten] options: {}
2019-09-02T10:24:01.511+0200 I -        [initandlisten] Detected data files in /data/db created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2019-09-02T10:24:01.511+0200 I STORAGE  [initandlisten] 
2019-09-02T10:24:01.511+0200 I STORAGE  [initandlisten] ** WARNING: Using the XFS filesystem is strongly recommended with the WiredTiger storage engine
2019-09-02T10:24:01.511+0200 I STORAGE  [initandlisten] **          See http://dochub.mongodb.org/core/prodnotes-filesystem
2019-09-02T10:24:01.511+0200 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=256M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),statistics_log=(wait=0),verbose=(recovery_progress),
2019-09-02T10:24:02.144+0200 E STORAGE  [initandlisten] WiredTiger error (-31802) [1567412642:144531][1288:0x7f3df7f4a0c0], txn-recover: unsupported WiredTiger file version: this build  only supports versions up to 2, and the file is version 3: WT_ERROR: non-specific WiredTiger error
2019-09-02T10:24:02.144+0200 E STORAGE  [initandlisten] WiredTiger error (0) [1567412642:144729][1288:0x7f3df7f4a0c0], txn-recover: WiredTiger is unable to read the recovery log.
2019-09-02T10:24:02.144+0200 E STORAGE  [initandlisten] WiredTiger error (0) [1567412642:144819][1288:0x7f3df7f4a0c0], txn-recover: This may be due to the log files being encrypted, being from an older version or due to corruption on disk
2019-09-02T10:24:02.144+0200 E STORAGE  [initandlisten] WiredTiger error (0) [1567412642:144892][1288:0x7f3df7f4a0c0], txn-recover: You should confirm that you have opened the database with the correct options including all encryption and compression options
2019-09-02T10:24:02.144+0200 E STORAGE  [initandlisten] WiredTiger error (-31802) [1567412642:144974][1288:0x7f3df7f4a0c0], txn-recover: Recovery failed: WT_ERROR: non-specific WiredTiger error
2019-09-02T10:24:02.148+0200 E -        [initandlisten] Assertion: 28595:-31802: WT_ERROR: non-specific WiredTiger error src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp 413
2019-09-02T10:24:02.148+0200 I STORAGE  [initandlisten] exception in initAndListen: Location28595: -31802: WT_ERROR: non-specific WiredTiger error, terminating
2019-09-02T10:24:02.148+0200 I NETWORK  [initandlisten] shutdown: going to close listening sockets...
2019-09-02T10:24:02.148+0200 I NETWORK  [initandlisten] removing socket file: /tmp/mongodb-27017.sock
2019-09-02T10:24:02.148+0200 I CONTROL  [initandlisten] now exiting
2019-09-02T10:24:02.148+0200 I CONTROL  [initandlisten] shutting down with code:100

I tried running `mongod --repair` but it had no effect

Here are is the mongod.log from around the time the server went down:

 

2019-09-01T06:23:18.248+0200 I NETWORK  [listener] connection accepted from 52.91.212.252:54124 #5850 (3 connections now open)
2019-09-01T06:23:18.464+0200 I NETWORK  [listener] connection accepted from 52.91.212.252:54165 #5851 (4 connections now open)
2019-09-01T06:23:18.857+0200 I ACCESS   [conn5851] Successfully authenticated as principal score on admin from client 52.91.212.252:54165
2019-09-01T06:24:18.750+0200 I NETWORK  [conn5851] end connection 52.91.212.252:54165 (3 connections now open)
2019-09-01T06:24:18.754+0200 I NETWORK  [conn5850] end connection 52.91.212.252:54124 (2 connections now open)
2019-09-01T06:37:07.978+0200 I NETWORK  [listener] connection accepted from 3.80.152.4:52107 #5852 (3 connections now open)
2019-09-01T06:37:08.210+0200 I NETWORK  [listener] connection accepted from 3.80.152.4:52147 #5853 (4 connections now open)
2019-09-01T06:37:08.750+0200 I ACCESS   [conn5853] Successfully authenticated as principal score on admin from client 3.80.152.4:52147
2019-09-01T06:37:09.401+0200 I NETWORK  [conn5852] end connection 3.80.152.4:52107 (3 connections now open)
2019-09-01T06:37:09.401+0200 I NETWORK  [conn5853] end connection 3.80.152.4:52147 (2 connections now open)
2019-09-01T06:39:27.846+0200 I NETWORK  [listener] connection accepted from 106.75.3.52:52660 #5854 (3 connections now open)
2019-09-01T06:39:28.226+0200 I NETWORK  [listener] connection accepted from 106.75.3.52:52990 #5855 (4 connections now open)
2019-09-01T06:39:28.970+0200 I NETWORK  [listener] connection accepted from 117.50.7.159:43274 #5856 (5 connections now open)
2019-09-01T06:39:28.970+0200 I NETWORK  [conn5856] Error receiving request from client: SSLHandshakeFailed: SSL handshake received but server is starte$
2019-09-01T06:39:28.970+0200 I NETWORK  [conn5856] end connection 117.50.7.159:43274 (4 connections now open)
2019-09-01T06:39:28.981+0200 I NETWORK  [conn5855] end connection 106.75.3.52:52990 (3 connections now open)
2019-09-01T06:39:29.000+0200 I NETWORK  [conn5854] end connection 106.75.3.52:52660 (2 connections now open)
2019-09-01T06:39:31.293+0200 I NETWORK  [listener] connection accepted from 117.50.7.159:44462 #5857 (3 connections now open)
2019-09-01T06:39:31.293+0200 I NETWORK  [conn5857] Error receiving request from client: ProtocolError: Client sent an HTTP request over a native MongoD$
2019-09-01T06:39:31.293+0200 I NETWORK  [conn5857] end connection 117.50.7.159:44462 (2 connections now open)
2019-09-01T06:39:33.229+0200 I NETWORK  [listener] connection accepted from 106.75.85.103:33012 #5858 (3 connections now open)
2019-09-01T06:39:33.229+0200 I NETWORK  [conn5858] Error receiving request from client: ProtocolError: Client sent an HTTP request over a native MongoD$
2019-09-01T06:39:33.229+0200 I NETWORK  [conn5858] end connection 106.75.85.103:33012 (2 connections now open)
2019-09-01T06:51:44.031+0200 I NETWORK  [listener] connection accepted from 100.24.38.59:48217 #5859 (3 connections now open)
2019-09-01T06:51:44.261+0200 I NETWORK  [listener] connection accepted from 100.24.38.59:48257 #5860 (4 connections now open)
2019-09-01T06:51:44.747+0200 I ACCESS   [conn5860] Successfully authenticated as principal score on admin from client 100.24.38.59:48257
2019-09-01T06:51:45.205+0200 I NETWORK  [conn5859] end connection 100.24.38.59:48217 (3 connections now open)
2019-09-01T06:51:45.205+0200 I NETWORK  [conn5860] end connection 100.24.38.59:48257 (2 connections now open)
2019-09-02T10:00:29.619+0200 I CONTROL  [main] ***** SERVER RESTARTED *****
2019-09-02T10:00:29.761+0200 I CONTROL  [initandlisten] MongoDB starting : pid=737 port=27017 dbpath=/var/lib/mongodb 64-bit host=score.real-tech.nl
2019-09-02T10:00:29.761+0200 I CONTROL  [initandlisten] db version v3.6.3
2019-09-02T10:00:29.761+0200 I CONTROL  [initandlisten] git version: 9586e557d54ef70f9ca4b43c26892cd55257e1a5
2019-09-02T10:00:29.761+0200 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.1.1  11 Sep 2018
2019-09-02T10:00:29.761+0200 I CONTROL  [initandlisten] allocator: tcmalloc
2019-09-02T10:00:29.761+0200 I CONTROL  [initandlisten] modules: none
2019-09-02T10:00:29.761+0200 I CONTROL  [initandlisten] build environment:
2019-09-02T10:00:29.761+0200 I CONTROL  [initandlisten]     distarch: x86_64
2019-09-02T10:00:29.761+0200 I CONTROL  [initandlisten]     target_arch: x86_64
2019-09-02T10:00:29.761+0200 I CONTROL  [initandlisten] options: { config: "/etc/mongod.conf", net: { bindIp: "0.0.0.0", port: 27017 }, processManageme$
2019-09-02T10:00:29.765+0200 I -        [initandlisten] Detected data files in /var/lib/mongodb created by the 'wiredTiger' storage engine, so setting $
2019-09-02T10:00:29.765+0200 I STORAGE  [initandlisten]
2019-09-02T10:00:29.765+0200 I STORAGE  [initandlisten] ** WARNING: Using the XFS filesystem is strongly recommended with the WiredTiger storage engine
2019-09-02T10:00:29.765+0200 I STORAGE  [initandlisten] **          See http://dochub.mongodb.org/core/prodnotes-filesystem
2019-09-02T10:00:29.766+0200 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=256M,session_max=20000,eviction=(threads_min=4,thread$
2019-09-02T10:00:31.073+0200 E STORAGE  [initandlisten] WiredTiger error (-31802) [1567411231:73319][737:0x7f3e2ae1f0c0], txn-recover: unsupported Wire$
2019-09-02T10:00:31.073+0200 E STORAGE  [initandlisten] WiredTiger error (0) [1567411231:73372][737:0x7f3e2ae1f0c0], txn-recover: WiredTiger is unable $
2019-09-02T10:00:31.073+0200 E STORAGE  [initandlisten] WiredTiger error (0) [1567411231:73382][737:0x7f3e2ae1f0c0], txn-recover: This may be due to th$
2019-09-02T10:00:31.073+0200 E STORAGE  [initandlisten] WiredTiger error (0) [1567411231:73389][737:0x7f3e2ae1f0c0], txn-recover: You should confirm th$
2019-09-02T10:00:31.073+0200 E STORAGE  [initandlisten] WiredTiger error (-31802) [1567411231:73406][737:0x7f3e2ae1f0c0], txn-recover: Recovery failed:$
2019-09-02T10:00:31.076+0200 E -        [initandlisten] Assertion: 28595:-31802: WT_ERROR: non-specific WiredTiger error src/mongo/db/storage/wiredtige$
2019-09-02T10:00:31.077+0200 I STORAGE  [initandlisten] exception in initAndListen: Location28595: -31802: WT_ERROR: non-specific WiredTiger error, ter$
2019-09-02T10:00:31.077+0200 I NETWORK  [initandlisten] shutdown: going to close listening sockets...
2019-09-02T10:00:31.077+0200 I NETWORK  [initandlisten] removing socket file: /tmp/mongodb-27017.sock
2019-09-02T10:00:31.077+0200 I CONTROL  [initandlisten] now exiting
2019-09-02T10:00:31.077+0200 I CONTROL  [initandlisten] shutting down with code:100
2019-09-02T10:00:48.242+0200 I CONTROL  [main] ***** SERVER RESTARTED *****

I made a backup of the dbpath folder on my local machine. How do I proceed in getting the database up and running?



 Comments   
Comment by Carl Champain (Inactive) [ 09/Oct/19 ]

Thanks for getting back to me, and I'm glad that you found a solution!
I'm going to close this ticket as it is now resolved.

Comment by Douwe de Vries [ 09/Oct/19 ]

Hi!

Sorry for the late reply! We tried restarting on 4.0 to no effect. Luckily a colleague who wasn’t in the office at the time, made a backup the day before so as far as we know we didn’t lose any data. We did a clean install and everything works perfectly now.

Thanks anyway!

Douwe

Comment by Carl Champain (Inactive) [ 09/Oct/19 ]

Hi douwemdevries@gmail.com,

Any updates on this issue?

Comment by Carl Champain (Inactive) [ 03/Sep/19 ]

Hi douwemdevries@gmail.com,

Thanks for reporting this issue!

Which version of mongod have you ran on this data path?

This is symptomatic of a crash with a 4.0 binary and an attempt to restart with a 3.6 binary. Would you please try to restart mongod with 4.0? Let us how it goes.

Thanks,
Carl

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