一次mongoDB的崩溃拉起记录

场景是这样的,重启后,我设置的一些参数失效了,为了令这些系统参数重新生效,便想重启mongoDB

[root@test-mysql01 ~]# service mongod restart
Stopping mongod:                                           [  OK  ]
Starting mongod:                                           [FAILED]

服务起不来,使用mongod启动

[root@test-mysql01 ~]# mongod
2015-08-19T15:53:37.212+0800 I JOURNAL  [initandlisten] journal dir=/data/db/journal
2015-08-19T15:53:37.224+0800 I JOURNAL  [initandlisten] recover : no journal files present, no recovery needed
2015-08-19T15:53:38.738+0800 I JOURNAL  [initandlisten] preallocateIsFaster=true 17.32
2015-08-19T15:53:40.353+0800 I JOURNAL  [initandlisten] preallocateIsFaster=true 19.6
2015-08-19T15:53:42.839+0800 I JOURNAL  [initandlisten] preallocateIsFaster=true 15.32
2015-08-19T15:53:42.840+0800 I JOURNAL  [initandlisten] preallocateIsFaster check took 5.616 secs
2015-08-19T15:53:42.840+0800 I JOURNAL  [initandlisten] preallocating a journal file /data/db/journal/prealloc.0
2015-08-19T15:53:45.081+0800 I -        [initandlisten]   File Preallocator Progress: 639631360/1073741824 59%
2015-08-19T15:53:48.185+0800 I -        [initandlisten]   File Preallocator Progress: 723517440/1073741824 67%
2015-08-19T15:53:51.283+0800 I -        [initandlisten]   File Preallocator Progress: 807403520/1073741824 75%
2015-08-19T15:53:54.448+0800 I -        [initandlisten]   File Preallocator Progress: 880803840/1073741824 82%
2015-08-19T15:53:57.268+0800 I -        [initandlisten]   File Preallocator Progress: 964689920/1073741824 89%
2015-08-19T15:54:14.533+0800 I JOURNAL  [initandlisten] preallocating a journal file /data/db/journal/prealloc.1
2015-08-19T15:54:17.056+0800 I -        [initandlisten]   File Preallocator Progress: 629145600/1073741824 58%
2015-08-19T15:54:20.365+0800 I -        [initandlisten]   File Preallocator Progress: 723517440/1073741824 67%
2015-08-19T15:54:23.034+0800 I -        [initandlisten]   File Preallocator Progress: 796917760/1073741824 74%
2015-08-19T15:54:26.548+0800 I -        [initandlisten]   File Preallocator Progress: 901775360/1073741824 83%
2015-08-19T15:54:29.001+0800 I -        [initandlisten]   File Preallocator Progress: 1017118720/1073741824 94%
2015-08-19T15:54:49.597+0800 I JOURNAL  [initandlisten] preallocating a journal file /data/db/journal/prealloc.2
2015-08-19T15:54:52.102+0800 I -        [initandlisten]   File Preallocator Progress: 681574400/1073741824 63%
2015-08-19T15:54:55.390+0800 I -        [initandlisten]   File Preallocator Progress: 775946240/1073741824 72%
2015-08-19T15:54:58.312+0800 I -        [initandlisten]   File Preallocator Progress: 880803840/1073741824 82%
2015-08-19T15:55:01.271+0800 I -        [initandlisten]   File Preallocator Progress: 954204160/1073741824 88%
2015-08-19T15:55:04.304+0800 I -        [initandlisten]   File Preallocator Progress: 1048576000/1073741824 97%
2015-08-19T15:55:27.769+0800 I JOURNAL  [durability] Durability thread started
2015-08-19T15:55:27.770+0800 I JOURNAL  [journal writer] Journal writer thread started
2015-08-19T15:55:27.859+0800 I CONTROL  [initandlisten] MongoDB starting : pid=1962 port=27017 dbpath=/data/db 64-bit host=test-mysql01
2015-08-19T15:55:27.859+0800 I CONTROL  [initandlisten] ** WARNING: You are running this process as the root user, which is not recommended.
2015-08-19T15:55:27.859+0800 I CONTROL  [initandlisten] 
2015-08-19T15:55:27.859+0800 I CONTROL  [initandlisten] db version v3.0.5
2015-08-19T15:55:27.859+0800 I CONTROL  [initandlisten] git version: 8bc4ae20708dbb493cb09338d9e7be6698e4a3a3
2015-08-19T15:55:27.859+0800 I CONTROL  [initandlisten] build info: Linux ip-10-165-164-140 2.6.32-220.el6.x86_64 #1 SMP Wed Nov 9 08:03:13 EST 2011 x86_64 BOOST_LIB_VERSION=1_49
2015-08-19T15:55:27.859+0800 I CONTROL  [initandlisten] allocator: tcmalloc
2015-08-19T15:55:27.859+0800 I CONTROL  [initandlisten] options: {}
2015-08-19T15:55:28.023+0800 I INDEX    [initandlisten] allocating new ns file /data/db/local.ns, filling with zeroes...
2015-08-19T15:55:28.641+0800 I STORAGE  [FileAllocator] allocating new datafile /data/db/local.0, filling with zeroes...
2015-08-19T15:55:28.641+0800 I STORAGE  [FileAllocator] creating directory /data/db/_tmp
2015-08-19T15:55:28.696+0800 I STORAGE  [FileAllocator] done allocating datafile /data/db/local.0, size: 64MB,  took 0.014 secs
2015-08-19T15:55:28.747+0800 I NETWORK  [initandlisten] waiting for connections on port 27017

此处一直卡死,我选择ctrl+c跳出


^C2015-08-19T16:01:28.832+0800 I CONTROL  [signalProcessingThread] got signal 2 (Interrupt), will terminate after current cmd ends
2015-08-19T16:01:28.846+0800 I CONTROL  [signalProcessingThread] now exiting
2015-08-19T16:01:28.846+0800 I NETWORK  [signalProcessingThread] shutdown: going to close listening sockets...
2015-08-19T16:01:28.846+0800 I NETWORK  [signalProcessingThread] closing listening socket: 5
2015-08-19T16:01:28.847+0800 I NETWORK  [signalProcessingThread] closing listening socket: 6
2015-08-19T16:01:28.847+0800 I NETWORK  [signalProcessingThread] removing socket file: /tmp/mongodb-27017.sock
2015-08-19T16:01:28.847+0800 I NETWORK  [signalProcessingThread] shutdown: going to flush diaglog...
2015-08-19T16:01:28.847+0800 I NETWORK  [signalProcessingThread] shutdown: going to close sockets...
2015-08-19T16:01:28.847+0800 I STORAGE  [signalProcessingThread] shutdown: waiting for fs preallocator...
2015-08-19T16:01:28.847+0800 I STORAGE  [signalProcessingThread] shutdown: final commit...
2015-08-19T16:01:28.848+0800 I JOURNAL  [signalProcessingThread] journalCleanup...
2015-08-19T16:01:28.848+0800 I JOURNAL  [signalProcessingThread] removeJournalFiles
2015-08-19T16:01:28.924+0800 I JOURNAL  [signalProcessingThread] Terminating durability thread ...
2015-08-19T16:01:28.950+0800 I JOURNAL  [journal writer] Journal writer thread stopped
2015-08-19T16:01:28.950+0800 I JOURNAL  [durability] Durability thread stopped
2015-08-19T16:01:28.950+0800 I STORAGE  [signalProcessingThread] shutdown: closing all files...
2015-08-19T16:01:28.952+0800 I STORAGE  [signalProcessingThread] closeAllFiles() finished
2015-08-19T16:01:28.952+0800 I STORAGE  [signalProcessingThread] shutdown: removing fs lock...
2015-08-19T16:01:28.952+0800 I CONTROL  [signalProcessingThread] dbexit:  rc: 0
看到日志，是无法连入mongo的状态

使用mongo命令版连入

[root@test-mysql01 ~]# mongo
MongoDB shell version: 3.0.5
connecting to: test
2015-08-19T16:01:43.237+0800 W NETWORK  Failed to connect to 127.0.0.1:27017, reason: errno:111 Connection refused
2015-08-19T16:01:43.288+0800 E QUERY    Error: couldn't connect to server 127.0.0.1:27017 (127.0.0.1), connection attempt failed
    at connect (src/mongo/shell/mongo.js:179:14)
    at (connect):1:6 at src/mongo/shell/mongo.js:179
exception: connect failed

报了一个errno111，经过搜索，是数据文件目录下，有一个叫mongo.lock的文件锁住了进程

[root@test-mysql01 mongo]# rm mongod.lock 
rm: remove regular file `mongod.lock'? yes

删除这个lock
[root@test-mysql01 mongo]# ls
db-text.0  db-text.ns  heartexpert.0  heartexpert.ns  journal  local.0  local.ns  storage.bson  test.0  test.ns  wzy.0  wzy.1  wzy.ns  zkf.0  zkf.ns
重启mongod

[root@test-mysql01 mongo]# service mongod start
Starting mongod:                                           [FAILED]
[root@test-mysql01 mongo]# service mongod stop
Stopping mongod:                                           [  OK  ]
[root@test-mysql01 mongo]# service mongod start
Starting mongod:                                           [FAILED]

还是没成功，使用命令版连入
[root@test-mysql01 mongo]# mongo
MongoDB shell version: 3.0.5
connecting to: test
2015-08-19T16:12:29.764+0800 W NETWORK  Failed to connect to 127.0.0.1:27017, reason: errno:111 Connection refused
2015-08-19T16:12:29.767+0800 E QUERY    Error: couldn't connect to server 127.0.0.1:27017 (127.0.0.1), connection attempt failed
    at connect (src/mongo/shell/mongo.js:179:14)
    at (connect):1:6 at src/mongo/shell/mongo.js:179
exception: connect failed

依旧是同样的错误。

我们来查看mongo.log

2015-08-19T16:12:26.861+0800 I CONTROL  ***** SERVER RESTARTED *****
2015-08-19T16:12:26.894+0800 W -        [initandlisten] Detected unclean shutdown - /var/lib/mongo/mongod.lock is not empty.
2015-08-19T16:12:26.909+0800 I JOURNAL  [initandlisten] journal dir=/var/lib/mongo/journal
2015-08-19T16:12:26.909+0800 I JOURNAL  [initandlisten] recover begin
2015-08-19T16:12:26.909+0800 I JOURNAL  [initandlisten] info no lsn file in journal/ directory
2015-08-19T16:12:26.909+0800 I JOURNAL  [initandlisten] recover lsn: 0
2015-08-19T16:12:26.909+0800 I JOURNAL  [initandlisten] recover /var/lib/mongo/journal/j._0
2015-08-19T16:12:26.910+0800 I JOURNAL  [initandlisten] recover cleaning up
2015-08-19T16:12:26.910+0800 I JOURNAL  [initandlisten] removeJournalFiles
2015-08-19T16:12:26.954+0800 I JOURNAL  [initandlisten] recover done
2015-08-19T16:12:26.955+0800 I JOURNAL  [initandlisten] warning couldn't write to / rename file /var/lib/mongo/journal/prealloc.0: couldn't open file /var/lib/mongo/jo
urnal/prealloc.0 for writing errno:9 Bad file descriptor
2015-08-19T16:12:26.994+0800 I JOURNAL  [durability] Durability thread started
2015-08-19T16:12:26.995+0800 I JOURNAL  [journal writer] Journal writer thread started
2015-08-19T16:12:27.037+0800 I CONTROL  [initandlisten] MongoDB starting : pid=2209 port=27017 dbpath=/var/lib/mongo 64-bit host=test-mysql01
2015-08-19T16:12:27.037+0800 I CONTROL  [initandlisten] db version v3.0.5
2015-08-19T16:12:27.037+0800 I CONTROL  [initandlisten] git version: 8bc4ae20708dbb493cb09338d9e7be6698e4a3a3
2015-08-19T16:12:27.037+0800 I CONTROL  [initandlisten] build info: Linux ip-10-165-164-140 2.6.32-220.el6.x86_64 #1 SMP Wed Nov 9 08:03:13 EST 2011 x86_64 BOOST_LIB_V
ERSION=1_49
2015-08-19T16:12:27.038+0800 I CONTROL  [initandlisten] allocator: tcmalloc
2015-08-19T16:12:27.038+0800 I CONTROL  [initandlisten] options: { config: "/etc/mongod.conf", net: { bindIp: "0.0.0.0" }, processManagement: { fork: true, pidFilePath
: "/var/run/mongodb/mongod.pid" }, storage: { dbPath: "/var/lib/mongo" }, systemLog: { destination: "file", logAppend: true, path: "/var/log/mongodb/mongod.log" } }
2015-08-19T16:12:27.038+0800 I CONTROL  [initandlisten] couldn't open /var/lib/mongo/heartexpert.ns errno:13 Permission denied
2015-08-19T16:12:27.038+0800 F INDEX    [initandlisten] error couldn't open file /var/lib/mongo/heartexpert.ns terminating
2015-08-19T16:12:27.038+0800 I -        [initandlisten] Invariant failure false src/mongo/db/storage/mmap_v1/catalog/namespace_index.cpp 249
2015-08-19T16:12:27.047+0800 I CONTROL  [initandlisten]
 0xf74fc9 0xf11ce1 0xef5a92 0xd1fa6f 0xd4b77c 0xd4eadf 0x914ea5 0x7f5f31 0x7fa6f9 0x7f50657fdd5d 0x7f34f9

从日志中蓝字看到，mongo没有文件损坏，崩溃恢复完成，没有问题。

从日志中红字看到，无法打开heartexpert这个数据文件

检查数据文件权限

[root@test-mysql01 mongo]# ll
total 622632
-rw------- 1 mongod mongod  67108864 Aug 17 19:55 db-text.0
-rw------- 1 mongod mongod  16777216 Aug 17 19:55 db-text.ns
-rw------- 1 root   root    67108864 Aug 19 04:26 heartexpert.0
-rw------- 1 root   root    16777216 Aug 19 04:26 heartexpert.ns
drwxr-xr-x 2 mongod mongod      4096 Aug 19 16:12 journal
-rw------- 1 mongod mongod  67108864 Aug 19 04:27 local.0
-rw------- 1 mongod mongod  16777216 Aug 19 04:27 local.ns
-rwxr-xr-x 1 mongod mongod         5 Aug 19 16:12 mongod.lock
-rw-r--r-- 1 mongod mongod        69 Aug 13 13:11 storage.bson
-rw------- 1 mongod mongod  67108864 Aug 13 16:11 test.0
-rw------- 1 mongod mongod  16777216 Aug 13 16:11 test.ns
-rw------- 1 mongod mongod  67108864 Aug 19 09:51 wzy.0
-rw------- 1 root   root   134217728 Aug 19 09:51 wzy.1
-rw------- 1 mongod mongod  16777216 Aug 19 09:50 wzy.ns
-rw------- 1 mongod mongod  67108864 Aug 13 16:56 zkf.0
-rw------- 1 mongod mongod  16777216 Aug 13 16:56 zkf.ns

存在一些数据文件的用户与属组都是root

修改这些文件的用户与属组

chown mongod heartexpert.0

chgrp mongod heartexpert.ns

……

[root@test-mysql01 mongo]# ll
total 622628
-rw------- 1 mongod mongod  67108864 Aug 17 19:55 db-text.0
-rw------- 1 mongod mongod  16777216 Aug 17 19:55 db-text.ns
-rw------- 1 mongod mongod  67108864 Aug 19 04:26 heartexpert.0
-rw------- 1 mongod mongod  16777216 Aug 19 04:26 heartexpert.ns
drwxr-xr-x 2 mongod mongod      4096 Aug 19 16:12 journal
-rw------- 1 mongod mongod  67108864 Aug 19 04:27 local.0
-rw------- 1 mongod mongod  16777216 Aug 19 04:27 local.ns
-rw-r--r-- 1 mongod mongod        69 Aug 13 13:11 storage.bson
-rw------- 1 mongod mongod  67108864 Aug 13 16:11 test.0
-rw------- 1 mongod mongod  16777216 Aug 13 16:11 test.ns
-rw------- 1 mongod mongod  67108864 Aug 19 09:51 wzy.0
-rw------- 1 mongod mongod 134217728 Aug 19 09:51 wzy.1
-rw------- 1 mongod mongod  16777216 Aug 19 09:50 wzy.ns
-rw------- 1 mongod mongod  67108864 Aug 13 16:56 zkf.0
-rw------- 1 mongod mongod  16777216 Aug 13 16:56 zkf.ns
权限修改完毕，并删掉lock

重启服务

[root@test-mysql01 mongo]# service mongod stop
Stopping mongod:                                           [  OK  ]
[root@test-mysql01 mongo]# service mongod start
Starting mongod:                                           [  OK  ]
[root@test-mysql01 mongo]# mongo
MongoDB shell version: 3.0.5
connecting to: test

成功！