一次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

成功！