Saturday, 5 March 2016

Repairing MongoDB on a Raspberry Pi after a Power Cut

I was settling down to a glorious session on football stats analysis on my Raspberry Pi when I was appalled to see this:

pi@raspberrypi:~ $ sudo mongo
MongoDB shell version: 3.0.9
connecting to: test
2016-03-05T17:30:27.332+0000 W NETWORK  Failed to connect to 127.0.0.1:27017, reason: errno:111 Connection refused
2016-03-05T17:30:27.351+0000 E QUERY    Error: couldn't connect to server 127.0.0.1:27017 (127.0.0.1), connection attempt failed
    at Error (native)
    at connect (src/mongo/shell/mongo.js:179:14)
    at (connect):1:6 at src/mongo/shell/mongo.js:179
exception: connect failed

Nooooooooooooooo!

So to try and repair the situation.  Remember I'm a home tinkering geek who wants to help fellow geeks, not a hard-core IT professional.  Hence please don't scoff at me if you think this is easy stuff.

A quick search of the excellent MongoDB help documentation told me to look in the MongoDB log file for clues.  Here's what I saw:

pi@raspberrypi:~ $ tail /var/log/mongodb/mongod.log
2016-03-05T17:37:47.441+0000 I CONTROL  [initandlisten] build info: Linux PlusBerryPi 4.1.13-v7+ #826 SMP PREEMPT Fri Nov 13 20:19:03 GMT 2015 armv7l BOOST_LIB_VERSION=1_49
2016-03-05T17:37:47.441+0000 I CONTROL  [initandlisten] allocator: tcmalloc
2016-03-05T17:37:47.441+0000 I CONTROL  [initandlisten] options: { config: "/etc/mongodb.conf", net: { bindIp: "127.0.0.1" }, storage: { dbPath: "/var/lib/mongodb", engine: "mmapv1" }, systemLog: { destination: "file", logAppend: true, path: "/var/log/mongodb/mongod.log", quiet: true } }
2016-03-05T17:37:47.575+0000 W -        [initandlisten] Detected unclean shutdown - /var/lib/mongodb/mongod.lock is not empty.
2016-03-05T17:37:47.628+0000 I STORAGE  [initandlisten] ************** 
Unclean shutdown detected.
Please visit http://dochub.mongodb.org/core/repair for recovery instructions.
*************

(Key notable things shown in red).  Earlier this week we had a power cut which would have caused this unclean shutdown and appearance of the mongod.lock file.

So to fix it!

Looking at the weblink above it told me to do two things.  Firstly find and delete the mongod.lock file.  So I did:

pi@raspberrypi:~ $ cd /var/lib/mongodb
pi@raspberrypi:/var/lib/mongodb $ ls -l | grep lock
-rw-r--r-- 1 mongodb nogroup        5 Feb 21 10:18 mongod.lock
pi@raspberrypi:/var/lib/mongodb $ sudo rm mongod.lock

Secondly run a command to repair the database.  So I did:

pi@raspberrypi:/var/lib/mongodb $ sudo mongod --repair
2016-03-05T17:51:56.432+0000 I CONTROL  
2016-03-05T17:51:56.432+0000 W CONTROL  32-bit servers don't have journaling enabled by default. Please use --journal if you want durability.
2016-03-05T17:51:56.432+0000 I CONTROL  
2016-03-05T17:51:56.460+0000 I CONTROL  [initandlisten] MongoDB starting : pid=1832 port=27017 dbpath=/data/db 32-bit host=raspberrypi
2016-03-05T17:51:56.461+0000 I CONTROL  [initandlisten] db version v3.0.9
2016-03-05T17:51:56.461+0000 I CONTROL  [initandlisten] git version: 20d60d3491908f1ae252fe452300de3978a040c7
2016-03-05T17:51:56.461+0000 I CONTROL  [initandlisten] build info: Linux PlusBerryPi 4.1.13-v7+ #826 SMP PREEMPT Fri Nov 13 20:19:03 GMT 2015 armv7l BOOST_LIB_VERSION=1_49
2016-03-05T17:51:56.461+0000 I CONTROL  [initandlisten] allocator: tcmalloc
2016-03-05T17:51:56.461+0000 I CONTROL  [initandlisten] options: { repair: true }
2016-03-05T17:51:56.624+0000 I STORAGE  [initandlisten] exception in initAndListen: 29 Data directory /data/db not found., terminating
2016-03-05T17:51:56.624+0000 I CONTROL  [initandlisten] dbexit:  rc: 100

(Key notable things shown in red).  So still not working, arghhhh!

In terms of journaling, more on that at the end of this post.  In terms of the lack of /data/db, this was weird because I'd never created this directory nor known it to be there.  However never one to ignore a direct piece of device I did:

pi@raspberrypi:~ $ cd /
pi@raspberrypi:/ $ sudo mkdir data
pi@raspberrypi:/ $ cd data
pi@raspberrypi:/data $ sudo mkdir db
pi@raspberrypi:/data $ cd db

...and then...

pi@raspberrypi:/data/db $ sudo mongod --repair
2016-03-05T18:01:22.541+0000 I CONTROL  
2016-03-05T18:01:22.542+0000 W CONTROL  32-bit servers don't have journaling enabled by default. Please use --journal if you want durability.
2016-03-05T18:01:22.542+0000 I CONTROL  
2016-03-05T18:01:22.578+0000 I CONTROL  [initandlisten] MongoDB starting : pid=1079 port=27017 dbpath=/data/db 32-bit host=raspberrypi
2016-03-05T18:01:22.578+0000 I CONTROL  [initandlisten] db version v3.0.9
2016-03-05T18:01:22.579+0000 I CONTROL  [initandlisten] git version: 20d60d3491908f1ae252fe452300de3978a040c7
2016-03-05T18:01:22.579+0000 I CONTROL  [initandlisten] build info: Linux PlusBerryPi 4.1.13-v7+ #826 SMP PREEMPT Fri Nov 13 20:19:03 GMT 2015 armv7l BOOST_LIB_VERSION=1_49
2016-03-05T18:01:22.579+0000 I CONTROL  [initandlisten] allocator: tcmalloc
2016-03-05T18:01:22.579+0000 I CONTROL  [initandlisten] options: { repair: true }
2016-03-05T18:01:22.803+0000 I CONTROL  [initandlisten] ** WARNING: You are running this process as the root user, which is not recommended.
2016-03-05T18:01:22.804+0000 I CONTROL  [initandlisten] 
2016-03-05T18:01:22.804+0000 I CONTROL  [initandlisten] 
2016-03-05T18:01:22.804+0000 I CONTROL  [initandlisten] ** NOTE: This is a 32 bit MongoDB binary.
2016-03-05T18:01:22.804+0000 I CONTROL  [initandlisten] **       32 bit builds are limited to less than 2GB of data (or less with --journal).
2016-03-05T18:01:22.804+0000 I CONTROL  [initandlisten] **       Note that journaling defaults to off for 32 bit and is currently off.
2016-03-05T18:01:22.804+0000 I CONTROL  [initandlisten] **       See http://dochub.mongodb.org/core/32bit
2016-03-05T18:01:22.805+0000 I CONTROL  [initandlisten] 
2016-03-05T18:01:22.805+0000 I CONTROL  [initandlisten] ** WARNING: soft rlimits too low. rlimits set to 7339 processes, 65536 files. Number of processes should be at least 32768 : 0.5 times number of files.
2016-03-05T18:01:22.805+0000 I CONTROL  [initandlisten] 
2016-03-05T18:01:22.806+0000 I STORAGE  [initandlisten] finished checking dbs
2016-03-05T18:01:22.815+0000 I CONTROL  [initandlisten] now exiting
2016-03-05T18:01:22.816+0000 I NETWORK  [initandlisten] shutdown: going to close listening sockets...
2016-03-05T18:01:22.816+0000 I NETWORK  [initandlisten] removing socket file: /tmp/mongodb-27017.sock
2016-03-05T18:01:22.816+0000 I NETWORK  [initandlisten] shutdown: going to flush diaglog...
2016-03-05T18:01:22.816+0000 I NETWORK  [initandlisten] shutdown: going to close sockets...
2016-03-05T18:01:22.816+0000 I STORAGE  [initandlisten] shutdown: waiting for fs preallocator...
2016-03-05T18:01:22.817+0000 I STORAGE  [initandlisten] shutdown: closing all files...
2016-03-05T18:01:22.817+0000 I STORAGE  [initandlisten] closeAllFiles() finished
2016-03-05T18:01:22.817+0000 I STORAGE  [initandlisten] shutdown: removing fs lock...
2016-03-05T18:01:22.817+0000 I CONTROL  [initandlisten] dbexit:  rc: 0

A warning but no errors which is good!

I could then do:

pi@raspberrypi:/data/db $ sudo service mongodb start

...and check it quickly by doing this in a browser:



Joy of joy, we're back in the room!!

So I could then do:

pi@raspberrypi:/data/db $ sudo mongo
MongoDB shell version: 3.0.9
connecting to: test
Server has startup warnings: 
2016-03-05T18:02:07.761+0000 I CONTROL  [initandlisten] 
2016-03-05T18:02:07.761+0000 I CONTROL  [initandlisten] ** NOTE: This is a 32 bit MongoDB binary.
2016-03-05T18:02:07.761+0000 I CONTROL  [initandlisten] **       32 bit builds are limited to less than 2GB of data (or less with --journal).
2016-03-05T18:02:07.761+0000 I CONTROL  [initandlisten] **       Note that journaling defaults to off for 32 bit and is currently off.
2016-03-05T18:02:07.761+0000 I CONTROL  [initandlisten] **       See http://dochub.mongodb.org/core/32bit
2016-03-05T18:02:07.762+0000 I CONTROL  [initandlisten] 
> use Footie
switched to db Footie

Let the fun begin!!

A point on "journaling" (which is mentioned again above).  The MongoDB help pages state:

To provide durability in the event of a failure, MongoDB uses write ahead logging to on-disk journal files.

...and

With journaling, the recovery process:
  1. Looks in the data files to find the identifier of the last checkpoint.
  2. Searches in the journal files for the record that matches the identifier of the last checkpoint.
  3. Apply the operations in the journal files since the last checkpoint.

...so looks like something that could have helped me with my power cut.  I think I'll just shutdown MongoDB at the end of each session.