Mongod FAILS to start after server reboot

Please HELP if you could be so kind…After Sunday reboot by Linux SA, I get in /var/log/mongdb/mongod.log …

2020-12-04T06:22:33.615+0200 I COMMAND  [conn102] killcursors: found 0 of 1
2020-12-04T06:22:45.243+0200 I COMMAND  [conn102] killcursors: found 0 of 1
2020-12-04T17:03:09.330+0200 I NETWORK  [conn51] end connection 127.0.0.1:54872 (31 connections now open)
2020-12-04T17:03:09.331+0200 I NETWORK  [conn50] end connection 127.0.0.1:54870 (30 connections now open)
2020-12-04T17:04:01.538+0200 I NETWORK  [conn115] end connection 127.0.0.1:37508 (29 connections now open)
2020-12-04T17:04:01.539+0200 I NETWORK  [conn112] end connection 127.0.0.1:37502 (28 connections now open)
2020-12-04T17:04:01.540+0200 I NETWORK  [conn118] end connection 127.0.0.1:37514 (27 connections now open)
2020-12-04T17:04:01.540+0200 I NETWORK  [conn119] end connection 127.0.0.1:37516 (26 connections now open)
2020-12-04T17:04:01.541+0200 I NETWORK  [conn117] end connection 127.0.0.1:37512 (25 connections now open)
2020-12-04T17:04:01.542+0200 I NETWORK  [conn113] end connection 127.0.0.1:37504 (24 connections now open)
2020-12-04T17:04:01.542+0200 I NETWORK  [conn116] end connection 127.0.0.1:37510 (23 connections now open)
2020-12-04T17:04:01.542+0200 I NETWORK  [conn114] end connection 127.0.0.1:37506 (22 connections now open)
2020-12-04T17:04:01.542+0200 I NETWORK  [conn121] end connection 127.0.0.1:37520 (22 connections now open)
2020-12-04T17:04:01.543+0200 I NETWORK  [conn120] end connection 127.0.0.1:37518 (20 connections now open)
2020-12-04T17:04:29.544+0200 I NETWORK  [conn110] end connection 127.0.0.1:37498 (19 connections now open)
2020-12-04T17:04:29.546+0200 I NETWORK  [conn106] end connection 127.0.0.1:37490 (18 connections now open)
2020-12-04T17:04:29.546+0200 I NETWORK  [conn107] end connection 127.0.0.1:37492 (17 connections now open)
2020-12-04T17:04:29.550+0200 I NETWORK  [conn105] end connection 127.0.0.1:37488 (16 connections now open)
2020-12-04T17:04:29.550+0200 I NETWORK  [conn104] end connection 127.0.0.1:37486 (15 connections now open)
2020-12-04T17:04:29.551+0200 I NETWORK  [conn103] end connection 127.0.0.1:37484 (14 connections now open)
2020-12-04T17:04:29.552+0200 I NETWORK  [conn109] end connection 127.0.0.1:37496 (13 connections now open)
2020-12-04T17:04:29.552+0200 I NETWORK  [conn102] end connection 127.0.0.1:37482 (12 connections now open)
2020-12-04T17:04:29.553+0200 I NETWORK  [conn108] end connection 127.0.0.1:37494 (11 connections now open)
2020-12-04T17:04:29.554+0200 I NETWORK  [conn111] end connection 127.0.0.1:37500 (10 connections now open)
2020-12-06T15:02:01.043+0200 I CONTROL  [signalProcessingThread] got signal 15 (Terminated), will terminate after current cmd ends
2020-12-06T15:02:01.044+0200 I CONTROL  [signalProcessingThread] now exiting
2020-12-06T15:02:01.044+0200 I NETWORK  [signalProcessingThread] shutdown: going to close listening sockets...
2020-12-06T15:02:01.044+0200 I NETWORK  [signalProcessingThread] closing listening socket: 6
2020-12-06T15:02:01.044+0200 I NETWORK  [signalProcessingThread] closing listening socket: 7
2020-12-06T15:02:01.044+0200 I NETWORK  [signalProcessingThread] removing socket file: /tmp/mongodb-27017.sock
2020-12-06T15:02:01.044+0200 I NETWORK  [signalProcessingThread] shutdown: going to flush diaglog...
2020-12-06T15:02:01.044+0200 I NETWORK  [signalProcessingThread] shutdown: going to close sockets...
2020-12-06T15:02:01.046+0200 I NETWORK  [conn53] end connection 127.0.0.1:54880 (9 connections now open)
2020-12-06T15:02:01.047+0200 I NETWORK  [conn59] end connection 127.0.0.1:54892 (9 connections now open)
2020-12-06T15:02:01.047+0200 I NETWORK  [conn55] end connection 127.0.0.1:54884 (9 connections now open)
2020-12-06T15:02:01.047+0200 I NETWORK  [conn56] end connection 127.0.0.1:54886 (9 connections now open)
2020-12-06T15:02:01.048+0200 I NETWORK  [conn60] end connection 127.0.0.1:54894 (9 connections now open)
2020-12-06T15:02:01.048+0200 I NETWORK  [conn52] end connection 127.0.0.1:54878 (9 connections now open)
2020-12-06T15:02:01.048+0200 I NETWORK  [conn57] end connection 127.0.0.1:54888 (9 connections now open)
2020-12-06T15:02:01.049+0200 I NETWORK  [conn61] end connection 127.0.0.1:54896 (9 connections now open)
2020-12-06T15:02:01.049+0200 I NETWORK  [conn54] end connection 127.0.0.1:54882 (9 connections now open)
2020-12-06T15:02:01.050+0200 I NETWORK  [conn58] end connection 127.0.0.1:54890 (9 connections now open)
2020-12-06T15:02:01.051+0200 I STORAGE  [signalProcessingThread] WiredTigerKVEngine shutting down
2020-12-06T15:02:01.184+0200 I STORAGE  [signalProcessingThread] shutdown: removing fs lock...
2020-12-06T15:02:01.184+0200 I CONTROL  [signalProcessingThread] dbexit:  rc: 0
2020-12-06T15:08:10.552+0200 I CONTROL  ***** SERVER RESTARTED *****
2020-12-06T15:08:10.692+0200 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=23G,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),
2020-12-06T15:08:10.904+0200 E STORAGE  [initandlisten] WiredTiger (-31802) [1607260090:904931][25075:0x7f3b75fadc20], file:WiredTiger.wt, connection: WiredTiger.wt read error: failed to read 4096 bytes at offset 0: WT_ERROR: non-specific WiredTiger error
2020-12-06T15:08:10.922+0200 I -        [initandlisten] Assertion: 28595:-31802: WT_ERROR: non-specific WiredTiger error
2020-12-06T15:08:11.208+0200 I STORAGE  [initandlisten] exception in initAndListen: 28595 -31802: WT_ERROR: non-specific WiredTiger error, terminating
2020-12-06T15:08:11.208+0200 I CONTROL  [initandlisten] dbexit:  rc: 100

Now when I manually start as root, I get…
[root@esa360qv63 bin]# /usr/bin/mongod start -f /etc/mongod.conf
about to fork child process, waiting until server is ready for connections.
forked process: 13259
ERROR: child process failed, exited with error number 1
…my config file is …
[root@esa360qv63 bin]# cat /etc/mongod.conf

mongo.conf

systemLog:
destination: file
logAppend: true
path: “/var/log/mongodb/mongod.log”

storage:
dbPath: /mongodata
journal:
enabled: true
engine: wiredTiger

processManagement:
fork: true
pidFilePath: /var/run/mongodb/mongod3.pid

net:
port: 27017
bindIp: 127.0.0.1 # Listen to local interface only, comment to listen on all interfaces.

[root@esa360qv63 bin]# cat /etc/redhat-release
Red Hat Enterprise Linux Server release 6.10 (Santiago)
[root@esa360qv63 bin]# ulimit -a
core file size (blocks, -c) 0
data seg size (kbytes, -d) unlimited
scheduling priority (-e) 0
file size (blocks, -f) unlimited
pending signals (-i) 192623
max locked memory (kbytes, -l) 64
max memory size (kbytes, -m) unlimited
open files (-n) 1024
pipe size (512 bytes, -p) 8
POSIX message queues (bytes, -q) 819200
real-time priority (-r) 0
stack size (kbytes, -s) 10240
cpu time (seconds, -t) unlimited
max user processes (-u) 192623
virtual memory (kbytes, -v) unlimited
file locks (-x) unlimited
[root@esa360qv63 bin]#

Does above info help point me in right direct??? TIA for your kind inputs<<<<

Did your SA possibly make some changes to SELinux configuration?

Hello Jack, thank you for your kind help and time. Indeed, SA patched the Linux OS on Sunday 6 Dec after that mongodb fails to start back up. For your pointer I checked and find below, that new files/directories have been introduced on the day of the patch, 6 DEC 2020. Do you see any quick clues here, kindly advise?
[root@esa360qv63 selinux]# ls -altr
total 52
-rw-r–r-- 1 root root 2271 Mar 16 2015 semanage.conf
-rw-r–r-- 1 root root 76 Oct 25 2016 restorecond_user.conf
-rw-r–r-- 1 root root 113 Oct 25 2016 restorecond.conf
-rw-r–r--. 1 root root 447 Mar 15 2017 config
drwxr-xr-x. 5 root root 4096 Dec 6 2017 .
drwxr-xr-x. 6 root root 4096 Dec 6 14:16 targeted
drwxr-xr-x. 7 root root 4096 Dec 6 14:27 mls
drwxr-xr-x. 6 root root 4096 Dec 6 14:28 minimum
drwxr-xr-x. 200 root root 20480 Dec 6 16:55 …
[root@esa360qv63 selinux]# view config
[root@esa360qv63 selinux]# getenforce
Disabled
[root@esa360qv63 selinux]# pwd
/etc/selinux
[root@esa360qv63 selinux]#

SE Linux is disabled. So it is not that.

This is the error line:

2020-12-06T15:08:10.904+0200 E STORAGE [initandlisten] WiredTiger (-31802) [1607260090:904931][25075:0x7f3b75fadc20], file:WiredTiger.wt, connection: WiredTiger.wt read error: failed to read 4096 bytes at offset 0: WT_ERROR: non-specific WiredTiger error

What version of mongodb are you running ?

Thank you Chris for your kind assistance, time and input. Version of mongodb running is below…extracted from older entries in the /var/log/mongodb/mongod.log file…

2020-06-01T13:56:27.772+0300 I CONTROL  [initandlisten] db version v3.0.6
2020-06-01T13:56:27.772+0300 I CONTROL  [initandlisten] git version: 1ef45a23a4c5e3480ac919b28afcba3c615488f2
2020-06-01T13:56:27.772+0300 I CONTROL  [initandlisten] build info: Linux ip-10-67-194-123 2.6.32-220.el6.x86_64 #1 SMP Wed Nov 9 08:03:13 EST 2011 x86_64 BOOST_LIB_VERSION=1_49
2020-06-01T13:56:27.772+0300 I CONTROL  [initandlisten] allocator: tcmalloc
2020-06-01T13:56:27.772+0300 I CONTROL  [initandlisten] options: { config: "/etc/mongod.conf", net: { bindIp: "127.0.0.1", port: 27017 }, processManagement: { fork: true, pidFilePath: "/var/run/mongodb/mongod3.pid" }, storage: { dbPath: "/mongodata", engine: "wiredTiger", journal: { enabled: true } }, systemLog: { destination: "file", logAppend: true, path: "/var/log/mongodb/mongod.log" } }
2020-06-01T13:56:27.789+0300 I NETWORK  [initandlisten] waiting for connections on port 27017
2020-06-01T13:56:29.247+0300 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:35470 #1 (1 connection now open)
2020-06-01T13:56:29.247+0300 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:35472 #2 (2 connections now open)
2020-06-01T13:56:29.247+0300 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:35474 #3 (3 connections now open)
2020-06-01T13:56:29.248+0300 I NETWORK  [initandlisten] connection accepted from 127.0.0.1:35476 #4 (4 connections now
....<skipping subsequent entries>....

I got the OS patch SA applied over the weekend rolled back then tried to start up mongodb still I ran into same error, something seems broke with the storage engine…would anyone be able to help debug further to try to salvage what we have and restart the 3.0.6 mongodb engine?

after patch rollback:

[root@esa360qv63 mongodata]# cat /etc/redhat-release
Red Hat Enterprise Linux Server release 6.5 (Santiago)
From the database datafile directory, permissions look fine....
[root@esa360qv63 mongodata]# ls -alt Wired*
-rw-r--r-- 1 mongod mongod 902 Dec  6 15:02 WiredTiger.turtle
-rw-r--r-- 1 mongod mongod   0 Jun  1  2020 WiredTiger.wt
-rw-r--r-- 1 mongod mongod 534 Apr 24  2017 WiredTiger.basecfg
-rw-r--r-- 1 mongod mongod  46 Apr 24  2017 WiredTiger
-rw-r--r-- 1 mongod mongod  21 Apr 24  2017 WiredTiger.lock

the mongod.log file still reports the same error again… :frowning:

2020-12-08T23:09:01.963+0200 I CONTROL  ***** SERVER RESTARTED *****
2020-12-08T23:09:01.986+0200 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=23G,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),
2020-12-08T23:09:01.992+0200 E STORAGE  [initandlisten] WiredTiger (-31802) [1607461741:992830][626:0x7fb3cfe1ec20], file:WiredTiger.wt, connection: WiredTiger.wt read error: failed to read 4096 bytes at offset 0: WT_ERROR: non-specific WiredTiger error
2020-12-08T23:09:01.993+0200 I -        [initandlisten] Assertion: 28595:-31802: WT_ERROR: non-specific WiredTiger error
2020-12-08T23:09:01.993+0200 I STORAGE  [initandlisten] exception in initAndListen: 28595 -31802: WT_ERROR: non-specific WiredTiger error, terminating
2020-12-08T23:09:01.993+0200 I CONTROL  [initandlisten] dbexit:  rc: 100

Can anyone please help??? Much appreciated for your time and kindness…

Your WiredTiger.wt file being 0 bytes is a bad thing.

If you are running in a replica set then you can resync this node with the rest of the cluster.

If you are running standalone you will have to recover from backup.

1 Like

Thank you Chris…is there any way to salvage the various collectionxxx.wt files in this volume using some repair command? this is a standalone install inherited as-is.

No to my knowledge. Might be some one else knows definitively.