replica set startup log files, demonstrates slow start

gistfile1.txt

$ mongod --port 3001 --dbpath data.1 --replSet rs1
Wed Nov 26 06:53:44.447 [initandlisten] MongoDB starting : pid=4991 port=3001 dbpath=data.1 64-bit host=harry
Wed Nov 26 06:53:44.447 [initandlisten] db version v2.4.9
Wed Nov 26 06:53:44.447 [initandlisten] git version: nogitversion
Wed Nov 26 06:53:44.447 [initandlisten] build info: Linux orlo 3.2.0-58-generic #88-Ubuntu SMP Tue Dec 3 17:37:58 UTC 2013 x86_64 BOOST_LIB_VERSION=1_54
Wed Nov 26 06:53:44.447 [initandlisten] allocator: tcmalloc
Wed Nov 26 06:53:44.447 [initandlisten] options: { dbpath: "data.1", port: 3001, replSet: "rs1" }
Wed Nov 26 06:53:44.517 [initandlisten] journal dir=data.1/journal
Wed Nov 26 06:53:44.518 [initandlisten] recover : no journal files present, no recovery needed
Wed Nov 26 06:53:47.440 [initandlisten] preallocateIsFaster=true 32.44
Wed Nov 26 06:53:51.173 [initandlisten] preallocateIsFaster=true 51.38
Wed Nov 26 06:53:57.518 [initandlisten] preallocateIsFaster=true 55.26
Wed Nov 26 06:53:57.518 [initandlisten] preallocateIsFaster check took 12.999 secs
Wed Nov 26 06:53:57.518 [initandlisten] preallocating a journal file data.1/journal/prealloc.0
Wed Nov 26 06:54:10.945 [initandlisten] preallocating a journal file data.1/journal/prealloc.1
Wed Nov 26 06:54:24.336 [initandlisten] preallocating a journal file data.1/journal/prealloc.2
Wed Nov 26 06:54:38.281 [FileAllocator] allocating new datafile data.1/local.ns, filling with zeroes...
Wed Nov 26 06:54:38.281 [FileAllocator] creating directory data.1/_tmp
Wed Nov 26 06:54:38.328 [FileAllocator] done allocating datafile data.1/local.ns, size: 16MB,  took 0.022 secs
Wed Nov 26 06:54:38.328 [FileAllocator] allocating new datafile data.1/local.0, filling with zeroes...
Wed Nov 26 06:54:38.350 [FileAllocator] done allocating datafile data.1/local.0, size: 64MB,  took 0.022 secs
Wed Nov 26 06:54:38.353 [initandlisten] waiting for connections on port 3001
Wed Nov 26 06:54:38.353 [websvr] admin web console waiting for connections on port 4001
Wed Nov 26 06:54:38.355 [rsStart] replSet can't get local.system.replset config from self or any seed (EMPTYCONFIG)
Wed Nov 26 06:54:38.355 [rsStart] replSet info you may need to run replSetInitiate -- rs.initiate() in the shell -- if that is not already done
Wed Nov 26 06:54:48.356 [rsStart] replSet can't get local.system.replset config from self or any seed (EMPTYCONFIG)
Wed Nov 26 06:54:58.357 [rsStart] replSet can't get local.system.replset config from self or any seed (EMPTYCONFIG)
Wed Nov 26 06:54:58.917 [initandlisten] connection accepted from 127.0.0.1:53624 #1 (1 connection now open)
Wed Nov 26 06:55:04.999 [conn1] replSet replSetInitiate admin command received from client
Wed Nov 26 06:55:05.001 [conn1] replSet info initiate : no configuration specified.  Using a default configuration for the set
Wed Nov 26 06:55:05.001 [conn1] replSet created this configuration for initiation : { _id: "rs1", members: [ { _id: 0, host: "harry:3001" } ] }
Wed Nov 26 06:55:05.001 [conn1] replSet replSetInitiate config object parses ok, 1 members specified
Wed Nov 26 06:55:05.028 [conn1] replSet replSetInitiate all members seem up
Wed Nov 26 06:55:05.028 [conn1] ******
Wed Nov 26 06:55:05.028 [conn1] creating replication oplog of size: 12900MB...
Wed Nov 26 06:55:05.029 [FileAllocator] allocating new datafile data.1/local.1, filling with zeroes...
Wed Nov 26 06:55:05.097 [FileAllocator] done allocating datafile data.1/local.1, size: 2047MB,  took 0.067 secs
Wed Nov 26 06:55:05.097 [FileAllocator] allocating new datafile data.1/local.2, filling with zeroes...
Wed Nov 26 06:55:05.120 [FileAllocator] done allocating datafile data.1/local.2, size: 2047MB,  took 0.022 secs
Wed Nov 26 06:55:05.121 [FileAllocator] allocating new datafile data.1/local.3, filling with zeroes...
Wed Nov 26 06:55:05.144 [FileAllocator] done allocating datafile data.1/local.3, size: 2047MB,  took 0.022 secs
Wed Nov 26 06:55:05.144 [FileAllocator] allocating new datafile data.1/local.4, filling with zeroes...
Wed Nov 26 06:55:05.167 [FileAllocator] done allocating datafile data.1/local.4, size: 2047MB,  took 0.022 secs
Wed Nov 26 06:55:05.168 [FileAllocator] allocating new datafile data.1/local.5, filling with zeroes...
Wed Nov 26 06:55:05.191 [FileAllocator] done allocating datafile data.1/local.5, size: 2047MB,  took 0.023 secs
Wed Nov 26 06:55:05.191 [FileAllocator] allocating new datafile data.1/local.6, filling with zeroes...
Wed Nov 26 06:55:05.216 [FileAllocator] done allocating datafile data.1/local.6, size: 2047MB,  took 0.024 secs
Wed Nov 26 06:55:05.216 [FileAllocator] allocating new datafile data.1/local.7, filling with zeroes...
Wed Nov 26 06:55:05.239 [FileAllocator] done allocating datafile data.1/local.7, size: 2047MB,  took 0.022 secs
Wed Nov 26 06:55:05.241 [conn1] ******
Wed Nov 26 06:55:05.241 [conn1] replSet info saving a newer config version to local.system.replset
Wed Nov 26 06:55:05.245 [conn1] replSet saveConfigLocally done
Wed Nov 26 06:55:05.245 [conn1] replSet replSetInitiate config now saved locally.  Should come online in about a minute.
Wed Nov 26 06:55:05.245 [conn1] command admin.$cmd command: { replSetInitiate: undefined } ntoreturn:1 keyUpdates:0 locks(micros) W:218431 reslen:194 246ms
Wed Nov 26 06:55:08.357 [rsStart] replSet I am harry:3001
Wed Nov 26 06:55:08.357 [rsStart] replSet STARTUP2
Wed Nov 26 06:55:09.359 [rsSync] replSet SECONDARY
Wed Nov 26 06:55:09.359 [rsMgr] replSet info electSelf 0
Wed Nov 26 06:55:10.358 [rsMgr] replSet PRIMARY
Wed Nov 26 06:55:25.730 [conn1] replSet replSetReconfig config object parses ok, 2 members specified
Wed Nov 26 06:55:25.730 [conn1] couldn't connect to harry:3002: couldn't connect to server harry:3002
Wed Nov 26 06:55:25.731 [conn1] replSet cmufcc requestHeartbeat harry:3002 : 9001 socket exception [CONNECT_ERROR] server [harry:3002] 
Wed Nov 26 06:55:25.731 [conn1] replSet replSetReconfig exception: need most members up to reconfigure, not ok : harry:3002
Wed Nov 26 06:56:12.073 [conn1] replSet replSetReconfig config object parses ok, 2 members specified
Wed Nov 26 06:56:12.073 [conn1] couldn't connect to harry:3002: couldn't connect to server harry:3002
Wed Nov 26 06:56:12.074 [conn1] replSet cmufcc requestHeartbeat harry:3002 : 9001 socket exception [CONNECT_ERROR] server [harry:3002] 
Wed Nov 26 06:56:12.074 [conn1] replSet replSetReconfig exception: need most members up to reconfigure, not ok : harry:3002
Wed Nov 26 06:56:55.537 [conn1] replSet replSetReconfig config object parses ok, 2 members specified
Wed Nov 26 06:56:55.538 [conn1] couldn't connect to harry:3002: couldn't connect to server harry:3002
Wed Nov 26 06:56:55.538 [conn1] replSet cmufcc requestHeartbeat harry:3002 : 9001 socket exception [CONNECT_ERROR] server [harry:3002] 
Wed Nov 26 06:56:55.538 [conn1] replSet replSetReconfig exception: need most members up to reconfigure, not ok : harry:3002
Wed Nov 26 06:56:57.145 [conn1] replSet replSetReconfig config object parses ok, 2 members specified
Wed Nov 26 06:56:57.145 [conn1] couldn't connect to harry:3002: couldn't connect to server harry:3002
Wed Nov 26 06:56:57.146 [conn1] replSet cmufcc requestHeartbeat harry:3002 : 9001 socket exception [CONNECT_ERROR] server [harry:3002] 
Wed Nov 26 06:56:57.146 [conn1] replSet replSetReconfig exception: need most members up to reconfigure, not ok : harry:3002

Wed Nov 26 06:57:38.601 [conn1] replSet replSetReconfig config object parses ok, 2 members specified
Wed Nov 26 06:57:38.602 [conn1] replSet replSetReconfig [2]
Wed Nov 26 06:57:38.602 [conn1] replSet info saving a newer config version to local.system.replset
Wed Nov 26 06:57:41.665 [conn1] replSet saveConfigLocally done
Wed Nov 26 06:57:41.665 [conn1] replSet info : additive change to configuration
Wed Nov 26 06:57:41.665 [conn1] replSet replSetReconfig new config saved locally
Wed Nov 26 06:57:41.665 [conn1] command admin.$cmd command: { replSetReconfig: { _id: "rs1", version: 2, members: [ { _id: 0, host: "harry:3001" }, { _id: 1.0, host: "harry:3002" } ] } } ntoreturn:1 keyUpdates:0 locks(micros) W:3062332 reslen:37 3064ms
Wed Nov 26 06:57:41.665 [rsHealthPoll] replSet member harry:3002 is up
Wed Nov 26 06:57:41.665 [rsMgr] replSet total number of votes is even - add arbiter or give one member an extra vote
Wed Nov 26 06:57:44.284 [conn1] replSet replSetReconfig config object parses ok, 3 members specified
Wed Nov 26 06:57:44.284 [conn1] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:44.285 [conn1] replSet cmufcc requestHeartbeat harry:3003 : 9001 socket exception [CONNECT_ERROR] server [harry:3003] 
Wed Nov 26 06:57:44.285 [conn1] replSet replSetReconfig [2]
Wed Nov 26 06:57:44.285 [conn1] replSet info saving a newer config version to local.system.replset
Wed Nov 26 06:57:45.372 [conn1] replSet saveConfigLocally done
Wed Nov 26 06:57:45.372 [conn1] replSet info : additive change to configuration
Wed Nov 26 06:57:45.373 [conn1] replSet replSetReconfig new config saved locally
Wed Nov 26 06:57:45.373 [conn1] command admin.$cmd command: { replSetReconfig: { _id: "rs1", version: 3, members: [ { _id: 0, host: "harry:3001" }, { _id: 1, host: "harry:3002" }, { _id: 2.0, host: "harry:3003" } ] } } ntoreturn:1 keyUpdates:0 locks(micros) W:1087453 reslen:66 1089ms
Wed Nov 26 06:57:45.373 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:45.374 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:45.374 [rsHealthPoll] replset info harry:3003 heartbeat failed, retrying
Wed Nov 26 06:57:45.374 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:45.374 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:45.375 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:45.375 [rsHealthPoll] replSet info harry:3003 is down (or slow to respond): 
Wed Nov 26 06:57:45.375 [rsHealthPoll] replSet member harry:3003 is now in state DOWN
Wed Nov 26 06:57:47.375 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:47.376 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:47.376 [rsHealthPoll] replset info harry:3003 heartbeat failed, retrying
Wed Nov 26 06:57:47.376 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:47.377 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:47.377 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:49.378 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:49.378 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:49.378 [rsHealthPoll] replset info harry:3003 heartbeat failed, retrying
Wed Nov 26 06:57:49.378 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:49.379 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:49.379 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:51.380 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:51.380 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:51.380 [rsHealthPoll] replset info harry:3003 heartbeat failed, retrying
Wed Nov 26 06:57:51.380 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:51.381 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:51.381 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:53.381 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:53.382 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:53.382 [rsHealthPoll] replset info harry:3003 heartbeat failed, retrying
Wed Nov 26 06:57:53.382 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:53.382 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:53.382 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:53.760 [initandlisten] connection accepted from 127.0.0.1:53701 #2 (2 connections now open)
Wed Nov 26 06:57:55.383 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:55.383 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:55.383 [rsHealthPoll] replset info harry:3003 heartbeat failed, retrying
Wed Nov 26 06:57:55.384 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:55.384 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:55.384 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:55.762 [rsHealthPoll] replset info harry:3002 thinks that we are down
Wed Nov 26 06:57:55.762 [rsHealthPoll] replSet member harry:3002 is now in state STARTUP2
Wed Nov 26 06:57:57.386 [rsHealthPoll] replSet member harry:3003 is up
Wed Nov 26 06:58:06.292 [initandlisten] connection accepted from 127.0.0.1:53719 #3 (3 connections now open)
Wed Nov 26 06:58:07.389 [rsHealthPoll] replset info harry:3003 thinks that we are down
Wed Nov 26 06:58:07.389 [rsHealthPoll] replSet member harry:3003 is now in state STARTUP2
Wed Nov 26 06:58:09.765 [conn2] end connection 127.0.0.1:53701 (2 connections now open)
Wed Nov 26 06:58:09.766 [initandlisten] connection accepted from 127.0.0.1:53721 #4 (3 connections now open)
Wed Nov 26 06:58:12.419 [initandlisten] connection accepted from 127.0.0.1:53723 #5 (4 connections now open)
Wed Nov 26 06:58:12.522 [conn5] end connection 127.0.0.1:53723 (3 connections now open)
Wed Nov 26 06:58:12.933 [initandlisten] connection accepted from 127.0.0.1:53724 #6 (4 connections now open)
Wed Nov 26 06:58:13.544 [initandlisten] connection accepted from 127.0.0.1:53725 #7 (5 connections now open)
Wed Nov 26 06:58:13.767 [rsHealthPoll] replSet member harry:3002 is now in state RECOVERING
Wed Nov 26 06:58:14.549 [slaveTracking] build index local.slaves { _id: 1 }
Wed Nov 26 06:58:14.552 [slaveTracking] build index done.  scanned 0 total records. 0.002 secs
Wed Nov 26 06:58:15.767 [rsHealthPoll] replSet member harry:3002 is now in state SECONDARY
Wed Nov 26 06:58:22.299 [conn3] end connection 127.0.0.1:53719 (4 connections now open)
Wed Nov 26 06:58:22.300 [initandlisten] connection accepted from 127.0.0.1:53726 #8 (5 connections now open)
Wed Nov 26 06:58:22.706 [initandlisten] connection accepted from 127.0.0.1:53727 #9 (6 connections now open)
Wed Nov 26 06:58:22.955 [conn9] end connection 127.0.0.1:53727 (5 connections now open)
Wed Nov 26 06:58:23.368 [initandlisten] connection accepted from 127.0.0.1:53728 #10 (6 connections now open)
Wed Nov 26 06:58:23.393 [rsHealthPoll] replSet member harry:3003 is now in state RECOVERING
Wed Nov 26 06:58:23.833 [conn1] replSet { _id: "rs1", version: 4, members: [ { _id: 0, host: "harry:3001" }, { _id: 1, host: "harry:3002" }, { _id: 2, host: "harry:3003" }, { _id: 3.0, host: "harry:3003" } ] }
Wed Nov 26 06:58:23.833 [conn1] replSet replSetReconfig exception: bad replset config -- duplicate hosts in the config object?
Wed Nov 26 06:58:23.977 [initandlisten] connection accepted from 127.0.0.1:53730 #11 (7 connections now open)
Wed Nov 26 06:58:25.393 [rsHealthPoll] replSet member harry:3003 is now in state SECONDARY
Wed Nov 26 06:58:39.773 [conn4] end connection 127.0.0.1:53721 (6 connections now open)
Wed Nov 26 06:58:39.773 [initandlisten] connection accepted from 127.0.0.1:53733 #12 (7 connections now open)
Wed Nov 26 06:58:52.306 [conn8] end connection 127.0.0.1:53726 (6 connections now open)
Wed Nov 26 06:58:52.307 [initandlisten] connection accepted from 127.0.0.1:53735 #13 (7 connections now open)
Wed Nov 26 06:59:09.781 [conn12] end connection 127.0.0.1:53733 (6 connections now open)
Wed Nov 26 06:59:09.781 [initandlisten] connection accepted from 127.0.0.1:53739 #14 (7 connections now open)
Wed Nov 26 06:59:22.314 [conn13] end connection 127.0.0.1:53735 (6 connections now open)
Wed Nov 26 06:59:22.315 [initandlisten] connection accepted from 127.0.0.1:53741 #15 (7 connections now open)
Wed Nov 26 06:59:39.788 [conn14] end connection 127.0.0.1:53739 (6 connections now open)
Wed Nov 26 06:59:39.789 [initandlisten] connection accepted from 127.0.0.1:53745 #16 (7 connections now open)
Wed Nov 26 06:59:52.322 [conn15] end connection 127.0.0.1:53741 (6 connections now open)
Wed Nov 26 06:59:52.322 [initandlisten] connection accepted from 127.0.0.1:53747 #17 (7 connections now open)
Wed Nov 26 07:00:09.796 [conn16] end connection 127.0.0.1:53745 (6 connections now open)
Wed Nov 26 07:00:09.796 [initandlisten] connection accepted from 127.0.0.1:53751 #18 (7 connections now open)
Wed Nov 26 07:00:22.329 [conn17] end connection 127.0.0.1:53747 (6 connections now open)
Wed Nov 26 07:00:22.329 [initandlisten] connection accepted from 127.0.0.1:53753 #19 (7 connections now open)
Wed Nov 26 07:00:39.803 [conn18] end connection 127.0.0.1:53751 (6 connections now open)
Wed Nov 26 07:00:39.803 [initandlisten] connection accepted from 127.0.0.1:53757 #20 (7 connections now open)
Wed Nov 26 07:00:52.336 [conn19] end connection 127.0.0.1:53753 (6 connections now open)
Wed Nov 26 07:00:52.337 [initandlisten] connection accepted from 127.0.0.1:53759 #21 (7 connections now open)
Wed Nov 26 07:01:09.810 [conn20] end connection 127.0.0.1:53757 (6 connections now open)
Wed Nov 26 07:01:09.811 [initandlisten] connection accepted from 127.0.0.1:53763 #22 (7 connections now open)
Wed Nov 26 07:01:22.344 [conn21] end connection 127.0.0.1:53759 (6 connections now open)
Wed Nov 26 07:01:22.344 [initandlisten] connection accepted from 127.0.0.1:53765 #23 (8 connections now open)
Wed Nov 26 07:01:39.817 [conn22] end connection 127.0.0.1:53763 (6 connections now open)
Wed Nov 26 07:01:39.818 [initandlisten] connection accepted from 127.0.0.1:53769 #24 (7 connections now open)
Wed Nov 26 07:01:52.350 [conn23] end connection 127.0.0.1:53765 (6 connections now open)
Wed Nov 26 07:01:52.351 [initandlisten] connection accepted from 127.0.0.1:53771 #25 (7 connections now open)
Wed Nov 26 07:02:09.825 [conn24] end connection 127.0.0.1:53769 (6 connections now open)
Wed Nov 26 07:02:09.826 [initandlisten] connection accepted from 127.0.0.1:53775 #26 (7 connections now open)
Wed Nov 26 07:02:22.358 [conn25] end connection 127.0.0.1:53771 (6 connections now open)
Wed Nov 26 07:02:22.358 [initandlisten] connection accepted from 127.0.0.1:53777 #27 (7 connections now open)


$ mongod --port 3002 --replSet rs1 --dbpath data.2
Wed Nov 26 06:56:07.105 [initandlisten] MongoDB starting : pid=5097 port=3002 dbpath=data.2 64-bit host=harry
Wed Nov 26 06:56:07.106 [initandlisten] db version v2.4.9
Wed Nov 26 06:56:07.106 [initandlisten] git version: nogitversion
Wed Nov 26 06:56:07.106 [initandlisten] build info: Linux orlo 3.2.0-58-generic #88-Ubuntu SMP Tue Dec 3 17:37:58 UTC 2013 x86_64 BOOST_LIB_VERSION=1_54
Wed Nov 26 06:56:07.106 [initandlisten] allocator: tcmalloc
Wed Nov 26 06:56:07.106 [initandlisten] options: { dbpath: "data.2", port: 3002, replSet: "rs1" }
Wed Nov 26 06:56:07.165 [initandlisten] journal dir=data.2/journal
Wed Nov 26 06:56:07.165 [initandlisten] recover : no journal files present, no recovery needed
Wed Nov 26 06:56:09.967 [initandlisten] preallocateIsFaster=true 33
Wed Nov 26 06:56:14.512 [initandlisten] preallocateIsFaster=true 67.58
Wed Nov 26 06:56:19.290 [initandlisten] preallocateIsFaster=true 52.2
Wed Nov 26 06:56:19.290 [initandlisten] preallocateIsFaster check took 12.124 secs
Wed Nov 26 06:56:19.290 [initandlisten] preallocating a journal file data.2/journal/prealloc.0
Wed Nov 26 06:56:32.917 [initandlisten] preallocating a journal file data.2/journal/prealloc.1
Wed Nov 26 06:56:46.813 [initandlisten] preallocating a journal file data.2/journal/prealloc.2
Wed Nov 26 06:57:01.055 [FileAllocator] allocating new datafile data.2/local.ns, filling with zeroes...
Wed Nov 26 06:57:01.055 [FileAllocator] creating directory data.2/_tmp
Wed Nov 26 06:57:01.196 [FileAllocator] done allocating datafile data.2/local.ns, size: 16MB,  took 0.065 secs
Wed Nov 26 06:57:01.196 [FileAllocator] allocating new datafile data.2/local.0, filling with zeroes...
Wed Nov 26 06:57:01.263 [FileAllocator] done allocating datafile data.2/local.0, size: 64MB,  took 0.066 secs
Wed Nov 26 06:57:01.267 [initandlisten] command local.$cmd command: { create: "startup_log", size: 10485760, capped: true } ntoreturn:1 keyUpdates:0  reslen:37 212ms
Wed Nov 26 06:57:01.268 [initandlisten] waiting for connections on port 3002
Wed Nov 26 06:57:01.269 [websvr] admin web console waiting for connections on port 4002
Wed Nov 26 06:57:01.273 [rsStart] replSet can't get local.system.replset config from self or any seed (EMPTYCONFIG)
Wed Nov 26 06:57:01.273 [rsStart] replSet info you may need to run replSetInitiate -- rs.initiate() in the shell -- if that is not already done


Wed Nov 27 06:57:11.274 [rsStart] replSet can't get local.system.replset config from self or any seed (EMPTYCONFIG)
Wed Nov 26 06:57:21.274 [rsStart] replSet can't get local.system.replset config from self or any seed (EMPTYCONFIG)
Wed Nov 26 06:57:31.275 [rsStart] replSet can't get local.system.replset config from self or any seed (EMPTYCONFIG)
Wed Nov 26 06:57:38.601 [initandlisten] connection accepted from 127.0.0.1:49296 #1 (1 connection now open)
Wed Nov 26 06:57:38.602 [initandlisten] connection accepted from 127.0.0.1:49297 #2 (2 connections now open)
Wed Nov 26 06:57:38.602 [conn1] end connection 127.0.0.1:49296 (1 connection now open)
Wed Nov 26 06:57:41.275 [rsStart] replSet can't get local.system.replset config from self or any seed (EMPTYCONFIG)
Wed Nov 26 06:57:51.276 [rsStart] trying to contact harry:3001
Wed Nov 26 06:57:53.761 [conn2] command admin.$cmd command: { replSetHeartbeat: "rs1", v: 3, pv: 1, checkEmpty: false, from: "harry:3001" } ntoreturn:1 keyUpdates:0  reslen:72 2093ms
Wed Nov 26 06:57:53.761 [rsStart] replSet I am harry:3002
Wed Nov 26 06:57:53.762 [rsStart] replSet got config version 3 from a remote, saving locally
Wed Nov 26 06:57:53.762 [rsStart] replSet info saving a newer config version to local.system.replset
Wed Nov 26 06:57:54.928 [rsStart] replSet saveConfigLocally done
Wed Nov 26 06:57:54.930 [rsStart] replSet STARTUP2
Wed Nov 26 06:57:54.930 [rsSync] ******
Wed Nov 26 06:57:54.930 [rsSync] creating replication oplog of size: 11872MB...
Wed Nov 26 06:57:55.762 [rsHealthPoll] replSet member harry:3001 is up
Wed Nov 26 06:57:55.762 [rsHealthPoll] replSet member harry:3001 is now in state PRIMARY
Wed Nov 26 06:57:55.762 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:55.763 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:55.763 [rsHealthPoll] replset info harry:3003 heartbeat failed, retrying
Wed Nov 26 06:57:55.763 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:55.764 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:55.764 [rsHealthPoll] couldn't connect to harry:3003: couldn't connect to server harry:3003
Wed Nov 26 06:57:55.764 [rsHealthPoll] replSet info harry:3003 is down (or slow to respond): 
Wed Nov 26 06:57:55.764 [rsHealthPoll] replSet member harry:3003 is now in state DOWN
Wed Nov 26 06:57:55.978 [FileAllocator] allocating new datafile data.2/local.1, filling with zeroes...
Wed Nov 26 06:57:56.029 [FileAllocator] done allocating datafile data.2/local.1, size: 2047MB,  took 0.05 secs
Wed Nov 26 06:57:56.030 [FileAllocator] allocating new datafile data.2/local.2, filling with zeroes...
Wed Nov 26 06:57:56.086 [FileAllocator] done allocating datafile data.2/local.2, size: 2047MB,  took 0.055 secs
Wed Nov 26 06:57:56.087 [FileAllocator] allocating new datafile data.2/local.3, filling with zeroes...
Wed Nov 26 06:57:56.153 [FileAllocator] done allocating datafile data.2/local.3, size: 2047MB,  took 0.066 secs
Wed Nov 26 06:57:56.154 [FileAllocator] allocating new datafile data.2/local.4, filling with zeroes...
Wed Nov 26 06:57:56.212 [FileAllocator] done allocating datafile data.2/local.4, size: 2047MB,  took 0.057 secs
Wed Nov 26 06:57:56.212 [FileAllocator] allocating new datafile data.2/local.5, filling with zeroes...
Wed Nov 26 06:57:56.258 [FileAllocator] done allocating datafile data.2/local.5, size: 2047MB,  took 0.045 secs
Wed Nov 26 06:57:56.259 [FileAllocator] allocating new datafile data.2/local.6, filling with zeroes...
Wed Nov 26 06:57:56.320 [FileAllocator] done allocating datafile data.2/local.6, size: 2047MB,  took 0.061 secs
Wed Nov 26 06:57:56.418 [rsSync] ******
Wed Nov 26 06:57:56.418 [rsSync] replSet initial sync pending
Wed Nov 26 06:57:56.418 [rsSync] replSet initial sync need a member to be primary or secondary to do our initial sync
Wed Nov 26 06:57:57.766 [rsHealthPoll] replSet member harry:3003 is up
Wed Nov 26 06:58:06.294 [initandlisten] connection accepted from 127.0.0.1:49348 #3 (2 connections now open)
Wed Nov 26 06:58:07.768 [rsHealthPoll] replset info harry:3003 thinks that we are down
Wed Nov 26 06:58:07.768 [rsHealthPoll] replSet member harry:3003 is now in state STARTUP2
Wed Nov 26 06:58:11.765 [conn2] end connection 127.0.0.1:49297 (1 connection now open)
Wed Nov 26 06:58:11.766 [initandlisten] connection accepted from 127.0.0.1:49350 #4 (2 connections now open)
Wed Nov 26 06:58:12.418 [rsSync] replSet initial sync pending
Wed Nov 26 06:58:12.418 [rsSync] replSet syncing to: harry:3001
Wed Nov 26 06:58:12.423 [rsSync] build index local.me { _id: 1 }
Wed Nov 26 06:58:12.426 [rsSync] build index done.  scanned 0 total records. 0.002 secs
Wed Nov 26 06:58:12.428 [rsSync] build index local.replset.minvalid { _id: 1 }
Wed Nov 26 06:58:12.429 [rsSync] build index done.  scanned 0 total records. 0.001 secs
Wed Nov 26 06:58:12.429 [rsSync] replSet initial sync drop all databases
Wed Nov 26 06:58:12.429 [rsSync] dropAllDatabasesExceptLocal 1
Wed Nov 26 06:58:12.429 [rsSync] replSet initial sync clone all databases
Wed Nov 26 06:58:12.430 [rsSync] replSet initial sync data copy, starting syncup
Wed Nov 26 06:58:12.430 [rsSync] oplog sync 1 of 3
Wed Nov 26 06:58:12.430 [rsSync] oplog sync 2 of 3
Wed Nov 26 06:58:12.431 [rsSync] replSet initial sync building indexes
Wed Nov 26 06:58:12.431 [rsSync] oplog sync 3 of 3
Wed Nov 26 06:58:12.431 [rsSync] replSet initial sync finishing up
Wed Nov 26 06:58:12.521 [rsSync] replSet set minValid=5475dc58:1
Wed Nov 26 06:58:12.522 [rsSync] replSet RECOVERING
Wed Nov 26 06:58:12.522 [rsSync] replSet initial sync done
Wed Nov 26 06:58:12.932 [rsBackgroundSync] replSet syncing to: harry:3001
Wed Nov 26 06:58:13.544 [rsSyncNotifier] replset setting oplog notifier to harry:3001
Wed Nov 26 06:58:14.523 [rsSync] replSet SECONDARY
Wed Nov 26 06:58:23.772 [rsHealthPoll] replSet member harry:3003 is now in state RECOVERING
Wed Nov 26 06:58:25.772 [rsHealthPoll] replSet member harry:3003 is now in state SECONDARY
Wed Nov 26 06:58:36.302 [conn3] end connection 127.0.0.1:49348 (1 connection now open)
Wed Nov 26 06:58:36.303 [initandlisten] connection accepted from 127.0.0.1:49360 #5 (2 connections now open)
Wed Nov 26 06:58:41.773 [conn4] end connection 127.0.0.1:49350 (1 connection now open)
Wed Nov 26 06:58:41.774 [initandlisten] connection accepted from 127.0.0.1:49362 #6 (2 connections now open)
Wed Nov 26 06:59:06.310 [conn5] end connection 127.0.0.1:49360 (1 connection now open)
Wed Nov 26 06:59:06.310 [initandlisten] connection accepted from 127.0.0.1:49366 #7 (2 connections now open)
Wed Nov 26 06:59:11.781 [conn6] end connection 127.0.0.1:49362 (1 connection now open)
Wed Nov 26 06:59:11.781 [initandlisten] connection accepted from 127.0.0.1:49368 #8 (2 connections now open)
Wed Nov 26 06:59:36.317 [conn7] end connection 127.0.0.1:49366 (1 connection now open)
Wed Nov 26 06:59:36.318 [initandlisten] connection accepted from 127.0.0.1:49372 #9 (2 connections now open)
Wed Nov 26 06:59:41.789 [conn8] end connection 127.0.0.1:49368 (1 connection now open)
Wed Nov 26 06:59:41.790 [initandlisten] connection accepted from 127.0.0.1:49374 #10 (2 connections now open)
Wed Nov 26 07:00:06.325 [conn9] end connection 127.0.0.1:49372 (1 connection now open)
Wed Nov 26 07:00:06.326 [initandlisten] connection accepted from 127.0.0.1:49378 #11 (2 connections now open)
Wed Nov 26 07:00:11.796 [conn10] end connection 127.0.0.1:49374 (1 connection now open)
Wed Nov 26 07:00:11.797 [initandlisten] connection accepted from 127.0.0.1:49380 #12 (3 connections now open)
Wed Nov 26 07:00:36.333 [conn11] end connection 127.0.0.1:49378 (1 connection now open)
Wed Nov 26 07:00:36.333 [initandlisten] connection accepted from 127.0.0.1:49384 #13 (2 connections now open)
Wed Nov 26 07:00:41.803 [conn12] end connection 127.0.0.1:49380 (1 connection now open)
Wed Nov 26 07:00:41.804 [initandlisten] connection accepted from 127.0.0.1:49386 #14 (2 connections now open)
Wed Nov 26 07:01:06.340 [conn13] end connection 127.0.0.1:49384 (1 connection now open)
Wed Nov 26 07:01:06.340 [initandlisten] connection accepted from 127.0.0.1:49390 #15 (2 connections now open)
Wed Nov 26 07:01:11.811 [conn14] end connection 127.0.0.1:49386 (1 connection now open)
Wed Nov 26 07:01:11.811 [initandlisten] connection accepted from 127.0.0.1:49392 #16 (2 connections now open)
Wed Nov 26 07:01:36.347 [conn15] end connection 127.0.0.1:49390 (1 connection now open)
Wed Nov 26 07:01:36.347 [initandlisten] connection accepted from 127.0.0.1:49396 #17 (2 connections now open)
Wed Nov 26 07:01:41.818 [conn16] end connection 127.0.0.1:49392 (1 connection now open)
Wed Nov 26 07:01:41.818 [initandlisten] connection accepted from 127.0.0.1:49398 #18 (2 connections now open)
Wed Nov 26 07:02:06.354 [conn17] end connection 127.0.0.1:49396 (1 connection now open)
Wed Nov 26 07:02:06.354 [initandlisten] connection accepted from 127.0.0.1:49402 #19 (2 connections now open)
Wed Nov 26 07:02:11.825 [conn18] end connection 127.0.0.1:49398 (1 connection now open)
Wed Nov 26 07:02:11.826 [initandlisten] connection accepted from 127.0.0.1:49404 #20 (2 connections now open)
Wed Nov 26 07:02:36.361 [conn19] end connection 127.0.0.1:49402 (1 connection now open)
Wed Nov 26 07:02:36.362 [initandlisten] connection accepted from 127.0.0.1:49408 #21 (2 connections now open)
Wed Nov 26 07:02:41.833 [conn20] end connection 127.0.0.1:49404 (1 connection now open)
Wed Nov 26 07:02:41.833 [initandlisten] connection accepted from 127.0.0.1:49410 #22 (2 connections now open)


$ mongod --port 3003 --replSet rs1 --dbpath data.3
Wed Nov 26 06:56:30.542 [initandlisten] MongoDB starting : pid=5104 port=3003 dbpath=data.3 64-bit host=harry
Wed Nov 26 06:56:30.542 [initandlisten] db version v2.4.9
Wed Nov 26 06:56:30.542 [initandlisten] git version: nogitversion
Wed Nov 26 06:56:30.542 [initandlisten] build info: Linux orlo 3.2.0-58-generic #88-Ubuntu SMP Tue Dec 3 17:37:58 UTC 2013 x86_64 BOOST_LIB_VERSION=1_54
Wed Nov 26 06:56:30.542 [initandlisten] allocator: tcmalloc
Wed Nov 26 06:56:30.542 [initandlisten] options: { dbpath: "data.3", port: 3003, replSet: "rs1" }
Wed Nov 26 06:56:32.918 [initandlisten] journal dir=data.3/journal
Wed Nov 26 06:56:32.918 [initandlisten] recover : no journal files present, no recovery needed
Wed Nov 26 06:57:04.410 [initandlisten] preallocateIsFaster=true 606.54
Wed Nov 26 06:57:07.388 [initandlisten] preallocateIsFaster=true 31.86
Wed Nov 26 06:57:13.510 [initandlisten] preallocateIsFaster=true 78.02
Wed Nov 26 06:57:13.510 [initandlisten] preallocateIsFaster check took 40.592 secs
Wed Nov 26 06:57:13.510 [initandlisten] preallocating a journal file data.3/journal/prealloc.0
Wed Nov 26 06:57:27.607 [initandlisten] preallocating a journal file data.3/journal/prealloc.1
Wed Nov 26 06:57:41.691 [initandlisten] preallocating a journal file data.3/journal/prealloc.2
Wed Nov 26 06:57:56.154 [FileAllocator] allocating new datafile data.3/local.ns, filling with zeroes...
Wed Nov 26 06:57:56.154 [FileAllocator] creating directory data.3/_tmp
Wed Nov 26 06:57:56.234 [FileAllocator] done allocating datafile data.3/local.ns, size: 16MB,  took 0.045 secs
Wed Nov 26 06:57:56.235 [FileAllocator] allocating new datafile data.3/local.0, filling with zeroes...
Wed Nov 26 06:57:56.281 [FileAllocator] done allocating datafile data.3/local.0, size: 64MB,  took 0.045 secs
Wed Nov 26 06:57:56.283 [initandlisten] command local.$cmd command: { create: "startup_log", size: 10485760, capped: true } ntoreturn:1 keyUpdates:0  reslen:37 129ms
Wed Nov 26 06:57:56.284 [initandlisten] waiting for connections on port 3003
Wed Nov 26 06:57:56.284 [websvr] admin web console waiting for connections on port 4003
Wed Nov 26 06:57:56.290 [rsStart] replSet can't get local.system.replset config from self or any seed (EMPTYCONFIG)
Wed Nov 26 06:57:56.290 [rsStart] replSet info you may need to run replSetInitiate -- rs.initiate() in the shell -- if that is not already done
Wed Nov 26 06:57:57.385 [initandlisten] connection accepted from 127.0.0.1:48868 #1 (1 connection now open)
Wed Nov 26 06:57:57.385 [initandlisten] connection accepted from 127.0.0.1:48869 #2 (2 connections now open)
Wed Nov 26 06:57:57.385 [conn1] end connection 127.0.0.1:48868 (0 connections now open)
Wed Nov 26 06:57:57.765 [initandlisten] connection accepted from 127.0.0.1:48870 #3 (2 connections now open)
Wed Nov 26 06:57:57.765 [initandlisten] connection accepted from 127.0.0.1:48871 #4 (3 connections now open)
Wed Nov 26 06:57:57.765 [conn3] end connection 127.0.0.1:48870 (1 connection now open)
Wed Nov 26 06:57:59.386 [conn2] end connection 127.0.0.1:48869 (1 connection now open)
Wed Nov 26 06:57:59.387 [initandlisten] connection accepted from 127.0.0.1:48872 #5 (2 connections now open)
Wed Nov 26 06:58:06.291 [rsStart] trying to contact harry:3001
Wed Nov 26 06:58:06.293 [rsStart] trying to contact harry:3002
Wed Nov 26 06:58:06.295 [rsStart] replSet I am harry:3003
Wed Nov 26 06:58:06.295 [rsStart] replSet got config version 3 from a remote, saving locally
Wed Nov 26 06:58:06.296 [rsStart] replSet info saving a newer config version to local.system.replset
Wed Nov 26 06:58:06.364 [rsStart] replSet saveConfigLocally done
Wed Nov 26 06:58:06.365 [rsStart] replSet STARTUP2
Wed Nov 26 06:58:06.366 [rsSync] ******
Wed Nov 26 06:58:06.366 [rsSync] creating replication oplog of size: 11254MB...
Wed Nov 26 06:58:06.377 [FileAllocator] allocating new datafile data.3/local.1, filling with zeroes...
Wed Nov 26 06:58:06.408 [FileAllocator] done allocating datafile data.3/local.1, size: 2047MB,  took 0.031 secs
Wed Nov 26 06:58:06.409 [FileAllocator] allocating new datafile data.3/local.2, filling with zeroes...
Wed Nov 26 06:58:06.443 [FileAllocator] done allocating datafile data.3/local.2, size: 2047MB,  took 0.033 secs
Wed Nov 26 06:58:06.444 [FileAllocator] allocating new datafile data.3/local.3, filling with zeroes...
Wed Nov 26 06:58:06.489 [FileAllocator] done allocating datafile data.3/local.3, size: 2047MB,  took 0.045 secs
Wed Nov 26 06:58:06.489 [FileAllocator] allocating new datafile data.3/local.4, filling with zeroes...
Wed Nov 26 06:58:06.535 [FileAllocator] done allocating datafile data.3/local.4, size: 2047MB,  took 0.045 secs
Wed Nov 26 06:58:06.535 [FileAllocator] allocating new datafile data.3/local.5, filling with zeroes...
Wed Nov 26 06:58:06.581 [FileAllocator] done allocating datafile data.3/local.5, size: 2047MB,  took 0.045 secs
Wed Nov 26 06:58:06.581 [FileAllocator] allocating new datafile data.3/local.6, filling with zeroes...
Wed Nov 26 06:58:06.638 [FileAllocator] done allocating datafile data.3/local.6, size: 2047MB,  took 0.056 secs
Wed Nov 26 06:58:06.705 [rsSync] ******
Wed Nov 26 06:58:06.705 [rsSync] replSet initial sync pending
Wed Nov 26 06:58:06.705 [rsSync] replSet initial sync need a member to be primary or secondary to do our initial sync
Wed Nov 26 06:58:08.296 [rsHealthPoll] replSet member harry:3002 is up
Wed Nov 26 06:58:08.296 [rsHealthPoll] replSet member harry:3001 is up
Wed Nov 26 06:58:08.296 [rsHealthPoll] replSet member harry:3002 is now in state STARTUP2
Wed Nov 26 06:58:08.296 [rsHealthPoll] replSet member harry:3001 is now in state PRIMARY
Wed Nov 26 06:58:14.298 [rsHealthPoll] replSet member harry:3002 is now in state RECOVERING
Wed Nov 26 06:58:16.298 [rsHealthPoll] replSet member harry:3002 is now in state SECONDARY
Wed Nov 26 06:58:22.705 [rsSync] replSet initial sync pending
Wed Nov 26 06:58:22.705 [rsSync] replSet syncing to: harry:3001
Wed Nov 26 06:58:22.710 [rsSync] build index local.me { _id: 1 }
Wed Nov 26 06:58:22.713 [rsSync] build index done.  scanned 0 total records. 0.002 secs
Wed Nov 26 06:58:22.715 [rsSync] build index local.replset.minvalid { _id: 1 }
Wed Nov 26 06:58:22.716 [rsSync] build index done.  scanned 0 total records. 0 secs
Wed Nov 26 06:58:22.716 [rsSync] replSet initial sync drop all databases
Wed Nov 26 06:58:22.717 [rsSync] dropAllDatabasesExceptLocal 1
Wed Nov 26 06:58:22.717 [rsSync] replSet initial sync clone all databases
Wed Nov 26 06:58:22.717 [rsSync] replSet initial sync data copy, starting syncup
Wed Nov 26 06:58:22.717 [rsSync] oplog sync 1 of 3
Wed Nov 26 06:58:22.717 [rsSync] oplog sync 2 of 3
Wed Nov 26 06:58:22.717 [rsSync] replSet initial sync building indexes
Wed Nov 26 06:58:22.717 [rsSync] oplog sync 3 of 3
Wed Nov 26 06:58:22.718 [rsSync] replSet initial sync finishing up
Wed Nov 26 06:58:22.954 [rsSync] replSet set minValid=5475dc58:1
Wed Nov 26 06:58:22.955 [rsSync] replSet RECOVERING
Wed Nov 26 06:58:22.955 [rsSync] replSet initial sync done
Wed Nov 26 06:58:23.368 [rsBackgroundSync] replSet syncing to: harry:3001
Wed Nov 26 06:58:23.771 [conn4] end connection 127.0.0.1:48871 (1 connection now open)
Wed Nov 26 06:58:23.771 [initandlisten] connection accepted from 127.0.0.1:48883 #6 (3 connections now open)
Wed Nov 26 06:58:23.976 [rsSyncNotifier] replset setting oplog notifier to harry:3001
Wed Nov 26 06:58:24.956 [rsSync] replSet SECONDARY
Wed Nov 26 06:58:29.394 [conn5] end connection 127.0.0.1:48872 (1 connection now open)
Wed Nov 26 06:58:29.394 [initandlisten] connection accepted from 127.0.0.1:48885 #7 (2 connections now open)
Wed Nov 26 06:58:53.778 [conn6] end connection 127.0.0.1:48883 (1 connection now open)
Wed Nov 26 06:58:53.779 [initandlisten] connection accepted from 127.0.0.1:48890 #8 (3 connections now open)
Wed Nov 26 06:58:59.401 [conn7] end connection 127.0.0.1:48885 (1 connection now open)
Wed Nov 26 06:58:59.402 [initandlisten] connection accepted from 127.0.0.1:48891 #9 (2 connections now open)
Wed Nov 26 06:59:23.785 [conn8] end connection 127.0.0.1:48890 (1 connection now open)
Wed Nov 26 06:59:23.785 [initandlisten] connection accepted from 127.0.0.1:48896 #10 (2 connections now open)
Wed Nov 26 06:59:29.409 [conn9] end connection 127.0.0.1:48891 (1 connection now open)
Wed Nov 26 06:59:29.409 [initandlisten] connection accepted from 127.0.0.1:48897 #11 (2 connections now open)
Wed Nov 26 06:59:53.792 [conn10] end connection 127.0.0.1:48896 (1 connection now open)
Wed Nov 26 06:59:53.793 [initandlisten] connection accepted from 127.0.0.1:48902 #12 (2 connections now open)
Wed Nov 26 06:59:59.417 [conn11] end connection 127.0.0.1:48897 (1 connection now open)
Wed Nov 26 06:59:59.417 [initandlisten] connection accepted from 127.0.0.1:48903 #13 (2 connections now open)
Wed Nov 26 07:00:23.799 [conn12] end connection 127.0.0.1:48902 (1 connection now open)
Wed Nov 26 07:00:23.800 [initandlisten] connection accepted from 127.0.0.1:48908 #14 (2 connections now open)
Wed Nov 26 07:00:29.424 [conn13] end connection 127.0.0.1:48903 (1 connection now open)
Wed Nov 26 07:00:29.425 [initandlisten] connection accepted from 127.0.0.1:48909 #15 (2 connections now open)
Wed Nov 26 07:00:53.807 [conn14] end connection 127.0.0.1:48908 (1 connection now open)
Wed Nov 26 07:00:53.807 [initandlisten] connection accepted from 127.0.0.1:48914 #16 (2 connections now open)
Wed Nov 26 07:00:59.432 [conn15] end connection 127.0.0.1:48909 (1 connection now open)
Wed Nov 26 07:00:59.432 [initandlisten] connection accepted from 127.0.0.1:48915 #17 (2 connections now open)
Wed Nov 26 07:01:23.813 [conn16] end connection 127.0.0.1:48914 (1 connection now open)
Wed Nov 26 07:01:23.814 [initandlisten] connection accepted from 127.0.0.1:48920 #18 (2 connections now open)
Wed Nov 26 07:01:29.440 [conn17] end connection 127.0.0.1:48915 (1 connection now open)
Wed Nov 26 07:01:29.440 [initandlisten] connection accepted from 127.0.0.1:48921 #19 (2 connections now open)
Wed Nov 26 07:01:53.821 [conn18] end connection 127.0.0.1:48920 (1 connection now open)
Wed Nov 26 07:01:53.821 [initandlisten] connection accepted from 127.0.0.1:48926 #20 (2 connections now open)
Wed Nov 26 07:01:59.447 [conn19] end connection 127.0.0.1:48921 (1 connection now open)
Wed Nov 26 07:01:59.448 [initandlisten] connection accepted from 127.0.0.1:48927 #21 (2 connections now open)
Wed Nov 26 07:02:23.828 [conn20] end connection 127.0.0.1:48926 (1 connection now open)
Wed Nov 26 07:02:23.829 [initandlisten] connection accepted from 127.0.0.1:48932 #22 (2 connections now open)
Wed Nov 26 07:02:29.455 [conn21] end connection 127.0.0.1:48927 (1 connection now open)
Wed Nov 26 07:02:29.455 [initandlisten] connection accepted from 127.0.0.1:48933 #23 (2 connections now open)
Wed Nov 26 07:02:53.836 [conn22] end connection 127.0.0.1:48932 (1 connection now open)
Wed Nov 26 07:02:53.836 [initandlisten] connection accepted from 127.0.0.1:48938 #24 (2 connections now open)
Wed Nov 26 07:02:59.463 [conn23] end connection 127.0.0.1:48933 (1 connection now open)
Wed Nov 26 07:02:59.463 [initandlisten] connection accepted from 127.0.0.1:48939 #25 (2 connections now open)



$ mongod --port 3004 --dbpath data.4
Wed Nov 26 07:06:36.084 [initandlisten] MongoDB starting : pid=5562 port=3004 dbpath=data.4 64-bit host=harry
Wed Nov 26 07:06:36.084 [initandlisten] db version v2.4.9
Wed Nov 26 07:06:36.084 [initandlisten] git version: nogitversion
Wed Nov 26 07:06:36.084 [initandlisten] build info: Linux orlo 3.2.0-58-generic #88-Ubuntu SMP Tue Dec 3 17:37:58 UTC 2013 x86_64 BOOST_LIB_VERSION=1_54
Wed Nov 26 07:06:36.084 [initandlisten] allocator: tcmalloc
Wed Nov 26 07:06:36.084 [initandlisten] options: { dbpath: "data.4", port: 3004 }
Wed Nov 26 07:06:36.137 [initandlisten] journal dir=data.4/journal
Wed Nov 26 07:06:36.137 [initandlisten] recover : no journal files present, no recovery needed
Wed Nov 26 07:06:39.184 [initandlisten] preallocateIsFaster=true 37.52
Wed Nov 26 07:06:44.239 [initandlisten] preallocateIsFaster=true 66.72
Wed Nov 26 07:06:49.372 [initandlisten] preallocateIsFaster=true 55.02
Wed Nov 26 07:06:49.373 [initandlisten] preallocateIsFaster check took 13.235 secs
Wed Nov 26 07:06:49.373 [initandlisten] preallocating a journal file data.4/journal/prealloc.0
Wed Nov 26 07:07:03.144 [initandlisten] preallocating a journal file data.4/journal/prealloc.1
Wed Nov 26 07:07:17.124 [initandlisten] preallocating a journal file data.4/journal/prealloc.2
Wed Nov 26 07:07:31.321 [FileAllocator] allocating new datafile data.4/local.ns, filling with zeroes...
Wed Nov 26 07:07:31.321 [FileAllocator] creating directory data.4/_tmp
Wed Nov 26 07:07:31.371 [FileAllocator] done allocating datafile data.4/local.ns, size: 16MB,  took 0.022 secs
Wed Nov 26 07:07:31.372 [FileAllocator] allocating new datafile data.4/local.0, filling with zeroes...
Wed Nov 26 07:07:31.394 [FileAllocator] done allocating datafile data.4/local.0, size: 64MB,  took 0.022 secs
Wed Nov 26 07:07:31.399 [websvr] admin web console waiting for connections on port 4004
Wed Nov 26 07:07:31.399 [initandlisten] waiting for connections on port 3004