Mongodb replica set polluted logs and arbiter in “initial startup”

Question

I'm running a replica set on with MongoBD v.2.0.3, here is the latest status:

+-----------------------------------------------------------------------------------------------------------------------+
 |       Member       |id|Up|  cctime   |Last heartbeat|Votes|Priority|      State       |   Messages    |  optime  |skew|
 |--------------------+--+--+-----------+--------------+-----+--------+------------------+---------------+----------+----|
 |127.0.1.1:27002     |0 |1 |13 hrs     |2 secs ago    |1    |1       |PRIMARY           |               |4f619079:2|1   |
 |--------------------+--+--+-----------+--------------+-----+--------+------------------+---------------+----------+----|
 |127.0.1.1:27003     |1 |1 |12 hrs     |1 sec ago     |1    |1       |SECONDARY         |               |4f619079:2|1   |
 |--------------------+--+--+-----------+--------------+-----+--------+------------------+---------------+----------+----|
 |127.0.1.1:27001     |2 |1 |2.5e+02 hrs|1 sec ago     |1    |0       |SECONDARY (hidden)|               |4f619079:2|-1  |
 |--------------------+--+--+-----------+--------------+-----+--------+------------------+---------------+----------+----|
 |127.0.1.1:27000 (me)|3 |1 |2.5e+02 hrs|              |1    |1       |ARBITER           |initial startup|0:0       |    |
 |--------------------+--+--+-----------+--------------+-----+--------+------------------+---------------+----------+----|
 |127.0.1.1:27004     |4 |1 |9.5 hrs    |2 secs ago    |1    |1       |SECONDARY         |               |4f619079:2|-1  |
 +-----------------------------------------------------------------------------------------------------------------------+

I'm puzzled by the following: 1) The arbiter always report the same message "initial startup" and "optime" of 0:0. What does the "initial startup" mean, and is it normal for this message not to change? Why the "optime" is always "0:0"? 2) What information does the skew column convey?

I've set up my replicas according to MongoDB's documentation and data seems to replicate across the set nicely, so no problem with that.

Another thing is that logs across all MongoDB hosts are polluted with such entries:

Thu Mar 15 03:25:29 [initandlisten] connection accepted from 127.0.0.1:38599 #112781
Thu Mar 15 03:25:29 [conn112781]  authenticate: { authenticate: 1, nonce: "99e2a4a5124541b9", user: "__system", key: "417d42d26643b2c2d014b89900700263" }
Thu Mar 15 03:25:32 [clientcursormon] mem (MB) res:12 virt:244 mapped:32
Thu Mar 15 03:25:34 [conn112779] end connection 127.0.0.1:38586
Thu Mar 15 03:25:34 [initandlisten] connection accepted from 127.0.0.1:38602 #112782
Thu Mar 15 03:25:34 [conn112782]  authenticate: { authenticate: 1, nonce: "a021e521ac9e19bc", user: "__system", key: "14507310174c89cdab3b82decb52b47c" }
Thu Mar 15 03:25:36 [conn112778] end connection 127.0.0.1:38585
Thu Mar 15 03:25:36 [initandlisten] connection accepted from 127.0.0.1:38604 #112783
Thu Mar 15 03:25:37 [conn112783]  authenticate: { authenticate: 1, nonce: "58bcf511e040b760", user: "__system", key: "24c5b20886f6d390d1ea8ea1c61fd109" }
Thu Mar 15 03:26:00 [conn112781] end connection 127.0.0.1:38599
Thu Mar 15 03:26:00 [initandlisten] connection accepted from 127.0.0.1:38615 #112784
Thu Mar 15 03:26:00 [conn112784]  authenticate: { authenticate: 1, nonce: "8a8f24fe012a03fe", user: "__system", key: "9b0be0c7fc790021b25aeb4511d85848" }
Thu Mar 15 03:26:01 [conn112780] end connection 127.0.0.1:38598
Thu Mar 15 03:26:01 [initandlisten] connection accepted from 127.0.0.1:38616 #112785
Thu Mar 15 03:26:01 [conn112785]  authenticate: { authenticate: 1, nonce: "420808aa9a12947", user: "__system", key: "90e8654a2eb3981219c370208989e97a" }
Thu Mar 15 03:26:04 [conn112782] end connection 127.0.0.1:38602
Thu Mar 15 03:26:04 [initandlisten] connection accepted from 127.0.0.1:38617 #112786
Thu Mar 15 03:26:04 [conn112786]  authenticate: { authenticate: 1, nonce: "b46ac4868db60973", user: "__system", key: "43cda53cc503bce942040ba8d3c6c3b1" }
Thu Mar 15 03:26:09 [conn112783] end connection 127.0.0.1:38604
Thu Mar 15 03:26:09 [initandlisten] connection accepted from 127.0.0.1:38621 #112787
Thu Mar 15 03:26:10 [conn112787]  authenticate: { authenticate: 1, nonce: "20fae7ed47cd1780", user: "__system", key: "f7b81c2d53ad48343e917e2db9125470" }
Thu Mar 15 03:26:30 [conn112784] end connection 127.0.0.1:38615
Thu Mar 15 03:26:30 [initandlisten] connection accepted from 127.0.0.1:38632 #112788
Thu Mar 15 03:26:31 [conn112788]  authenticate: { authenticate: 1, nonce: "38ee5b7b665d26be", user: "__system", key: "49c1f9f4e3b5cf2bf05bfcbb939ee422" }
Thu Mar 15 03:26:33 [conn112785] end connection 127.0.0.1:38616

It seems like many connections are established and dropped. Is that the replica set heartbeat?

Additional information

Arbiter config

dbpath=/var/lib/mongodb
logpath=/var/log/mongodb/mongodb.log
logappend=true
port = 27000
bind_ip = 127.0.1.1
rest = true
journal = true
replSet = myreplname
keyFile = /etc/mongodb/set.key
oplogSize = 8
quiet = true

Replica set member config

dbpath=/root/local/var/mongodb
logpath=/root/local/var/log/mongodb.log
logappend=true
port = 27002
bind_ip = 127.0.1.1
rest = true
journal = true
replSet = myreplname
keyFile = /root/local/etc/set.key
quiet = true

MongoDB instances are running on different machines and connect to each other over SSH tunnels setup in fully connected mesh.

Answer 1

The arbiter doesn't do anything besides participate in elections, so it has no further operations after startup. "Skew" is clock skew in seconds between this member and the others in the set. Yes, the connect / disconnect messages are heartbeats.