[SERVER-27181] one member of mongod replica rollback failed after After the connection with other node disconnected for some time Created: 25/Nov/16  Updated: 16/Dec/16  Resolved: 13/Dec/16

Status: Closed
Project: Core Server
Component/s: Replication
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: lei pei Assignee: Kelsey Schubert
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Participants:

 Description   

We have a replica with three mongods.
the version of mongod is 3.2.10.
one node was disconnected from others in network storm for testing.
now the network has recovery.but the node reconnected report
"Fatal assertion 28723 UnrecoverableRollbackError: need to rollback, but unable to determine common point between local and remote oplog: replica set fatal exception @ 18752"



 Comments   
Comment by lei pei [ 16/Dec/16 ]

hi, Thomas Schubert:
We have solved the problem now.
We avoid to use collMod to refresh ttl value If the ttl value of data is not changed now.

Comment by Kelsey Schubert [ 13/Dec/16 ]

Hi leipei2352@126.com,

From your responses, I do not see anything to indicate a bug in the MongoDB server. For MongoDB-related support discussion please post on the mongodb-users group or Stack Overflow with the mongodb tag. A question like this involving more discussion would be best posted on the mongodb-users group.

Kind regards,
Thomas

Comment by lei pei [ 01/Dec/16 ]

hi,Thomas,
We use oplogsize in config file like bellow:
fork = true
dbpath = /var/ceilometer
replSet = fsp
logappend = true
logpath = /var/log/xxxx/component/mongodb/mongodb.log
auth = true
smallfiles = true
oplogSize = 3072
bind_ip = 172.28.9.142,localhost
keyFile = /etc/mongodb/mongodb-keyfile

Comment by Kelsey Schubert [ 28/Nov/16 ]

Hi leipei2352@126.com,

This behavior may be expected if your oplog is not large enough to contain all the operations since the affected node when down. To determine if this is the case, would you please provide the output of the following command?

rs.printReplicationInfo()

Thank you,
Thomas

Comment by lei pei [ 28/Nov/16 ]

hi, Thomas:
1. The members of replica set will restart with ceilometer restarts on our hosts.
2. as "Rollbacks During Replica Set Failover" says, the previous primary node will rollback after it rejoins its replica set.
3. ceilometer service will refresh ttl index when it reconnect to primary of replica set or it is restarted.

Comment by lei pei [ 26/Nov/16 ]

We use mongodb as the backstage data store for the openstack ceilometer service.

We found that the ceilometer services refresh ttl index of collection as the ceilometer service start.
like this: coll.database.command('collMod',coll.name,index=

{'keyPattern':***,'expireAfterSeconds':ttl}

Whether there is this possibility: mongodb and ceilometer services alternately restart , ttl indexes of the new primary node are refreshed, and then the data of the previous primary rolls back,but collMod action on ttl index can not roll back?

Comment by lei pei [ 26/Nov/16 ]

log @ 172.28.9.140

2016-11-23T19:42:27.296+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:35886 #939 (178 connections now open)
2016-11-23T19:42:27.307+0800 I ACCESS   [conn939] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:27.316+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:35898 #940 (179 connections now open)
2016-11-23T19:42:27.318+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:35904 #941 (180 connections now open)
2016-11-23T19:42:27.327+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:35906 #942 (181 connections now open)
2016-11-23T19:42:27.327+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:35908 #943 (182 connections now open)
2016-11-23T19:42:27.328+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:35910 #944 (183 connections now open)
2016-11-23T19:42:27.334+0800 I ACCESS   [conn941] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:27.339+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:35912 #945 (184 connections now open)
2016-11-23T19:42:27.341+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:35914 #946 (185 connections now open)
2016-11-23T19:42:27.344+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:35916 #947 (186 connections now open)
2016-11-23T19:42:27.353+0800 I ACCESS   [conn947] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:27.355+0800 I ACCESS   [conn945] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:27.358+0800 I ACCESS   [conn946] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:27.360+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:35920 #948 (187 connections now open)
2016-11-23T19:42:27.363+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:35926 #949 (188 connections now open)
2016-11-23T19:42:27.366+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:35928 #950 (189 connections now open)
2016-11-23T19:42:27.368+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:35934 #951 (190 connections now open)
2016-11-23T19:42:27.369+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:35936 #952 (191 connections now open)
2016-11-23T19:42:27.372+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:35942 #953 (192 connections now open)
2016-11-23T19:42:27.372+0800 I ACCESS   [conn949] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:27.380+0800 I ACCESS   [conn952] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:27.389+0800 I ACCESS   [conn953] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:27.636+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:35996 #954 (193 connections now open)
2016-11-23T19:42:27.640+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36002 #955 (194 connections now open)
2016-11-23T19:42:27.641+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36006 #956 (195 connections now open)
2016-11-23T19:42:27.644+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36008 #957 (196 connections now open)
2016-11-23T19:42:27.645+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36010 #958 (197 connections now open)
2016-11-23T19:42:27.648+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36012 #959 (198 connections now open)
2016-11-23T19:42:27.653+0800 I ACCESS   [conn957] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:27.656+0800 I ACCESS   [conn955] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:27.658+0800 I ACCESS   [conn959] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:27.662+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36019 #960 (199 connections now open)
2016-11-23T19:42:27.665+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36024 #961 (200 connections now open)
2016-11-23T19:42:27.666+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36026 #962 (201 connections now open)
2016-11-23T19:42:27.666+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36028 #963 (202 connections now open)
2016-11-23T19:42:27.669+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36038 #964 (203 connections now open)
2016-11-23T19:42:27.670+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36042 #965 (204 connections now open)
2016-11-23T19:42:27.677+0800 I ACCESS   [conn961] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:27.680+0800 I ACCESS   [conn964] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:27.686+0800 I ACCESS   [conn965] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:28.190+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36086 #966 (205 connections now open)
2016-11-23T19:42:28.193+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36090 #967 (206 connections now open)
2016-11-23T19:42:28.208+0800 I ACCESS   [conn967] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:28.219+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36094 #968 (207 connections now open)
2016-11-23T19:42:28.223+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36100 #969 (208 connections now open)
2016-11-23T19:42:28.233+0800 I ACCESS   [conn969] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:30.773+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:59238 #970 (209 connections now open)
2016-11-23T19:42:30.773+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:59240 #971 (210 connections now open)
2016-11-23T19:42:30.783+0800 I ACCESS   [conn970] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:30.786+0800 I ACCESS   [conn971] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:30.788+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:59242 #972 (211 connections now open)
2016-11-23T19:42:30.798+0800 I ACCESS   [conn972] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:31.110+0800 I COMMAND  [conn817] getmore local.oplog.rs planSummary: COLLSCAN cursorid:14559503785 ntoreturn:0 keysExamined:0 docsExamined:149796 keyUpdates:0 writeConflicts:0 numYields:1251 nreturned:149796 reslen:4194308 locks:{ Global: { acquireCount: { r: 2504 } }, Database: { acquireCount: { r: 1252 } }, oplog: { acquireCount: { r: 1252 } } } 7032ms
2016-11-23T19:42:31.153+0800 I NETWORK  [conn817] end connection 172.28.0.4:35734 (210 connections now open)
2016-11-23T19:42:31.153+0800 I NETWORK  [conn794] end connection 172.28.0.4:35710 (209 connections now open)
2016-11-23T19:42:31.153+0800 I NETWORK  [conn812] end connection 172.28.0.4:35720 (208 connections now open)
2016-11-23T19:42:31.535+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36340 #973 (209 connections now open)
2016-11-23T19:42:32.737+0800 I ASIO     [ReplicationExecutor] dropping unhealthy pooled connection to 172.28.9.141:27017
2016-11-23T19:42:32.737+0800 I ASIO     [ReplicationExecutor] after drop, pool was empty, going to spawn some connections
2016-11-23T19:42:32.737+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T19:42:32.737+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.141:27017 - HostUnreachable: Connection refused
2016-11-23T19:42:32.737+0800 I REPL     [ReplicationExecutor] Error in heartbeat request to 172.28.9.141:27017; HostUnreachable: Connection refused
2016-11-23T19:42:32.737+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T19:42:32.738+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.141:27017 - HostUnreachable: Connection refused
2016-11-23T19:42:32.738+0800 I REPL     [ReplicationExecutor] Error in heartbeat request to 172.28.9.141:27017; HostUnreachable: Connection refused
2016-11-23T19:42:32.738+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T19:42:32.738+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.141:27017 - HostUnreachable: Connection refused
2016-11-23T19:42:32.738+0800 I REPL     [ReplicationExecutor] Error in heartbeat request to 172.28.9.141:27017; HostUnreachable: Connection refused
2016-11-23T19:42:33.191+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36574 #974 (210 connections now open)
2016-11-23T19:42:33.201+0800 I ACCESS   [conn974] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:39.764+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T19:42:39.764+0800 I COMMAND  [conn937] command local.oplog.rs command: getMore { getMore: 16870618613, collection: "oplog.rs", maxTimeMS: 5000, term: 9, lastKnownCommittedOpTime: { ts: Timestamp 1479901354000|4, t: 9 } } planSummary: COLLSCAN cursorid:16870618613 keysExamined:0 docsExamined:0 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:0 reslen:292 locks:{ Global: { acquireCount: { r: 6 } }, Database: { acquireCount: { r: 3 } }, oplog: { acquireCount: { r: 3 } } } protocol:op_command 5278ms
2016-11-23T19:42:39.765+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.141:27017 - HostUnreachable: Connection refused

Comment by lei pei [ 26/Nov/16 ]

log @ 172.28.9.140

2016-11-23T19:42:25.118+0800 I ACCESS   [conn836] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.118+0800 I ACCESS   [conn915] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.119+0800 I ACCESS   [conn828] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.120+0800 I ACCESS   [conn928] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.120+0800 I ACCESS   [conn845] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.120+0800 I ACCESS   [conn900] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.122+0800 I ACCESS   [conn901] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.122+0800 I ACCESS   [conn839] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.122+0800 I ACCESS   [conn914] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.122+0800 I ACCESS   [conn843] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.122+0800 I ACCESS   [conn834] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.122+0800 I ACCESS   [conn847] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.123+0800 I ACCESS   [conn837] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.123+0800 I ACCESS   [conn846] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.124+0800 I ACCESS   [conn862] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.124+0800 I ACCESS   [conn860] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.124+0800 I ACCESS   [conn822] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.124+0800 I ACCESS   [conn851] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.125+0800 I ACCESS   [conn926] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.125+0800 I ACCESS   [conn819] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.125+0800 I ACCESS   [conn841] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.125+0800 I ACCESS   [conn829] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.125+0800 I ACCESS   [conn902] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.126+0800 I ACCESS   [conn912] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.126+0800 I ACCESS   [conn864] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.126+0800 I ACCESS   [conn919] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.126+0800 I ACCESS   [conn889] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.127+0800 I ACCESS   [conn842] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.127+0800 I ACCESS   [conn904] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.127+0800 I ACCESS   [conn911] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.127+0800 I ACCESS   [conn907] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.127+0800 I ACCESS   [conn826] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.127+0800 I ACCESS   [conn923] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.127+0800 I ACCESS   [conn884] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.128+0800 I ACCESS   [conn924] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.129+0800 I ACCESS   [conn824] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.129+0800 I ACCESS   [conn854] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.129+0800 I ACCESS   [conn820] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.129+0800 I ACCESS   [conn852] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.130+0800 I ACCESS   [conn835] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.130+0800 I ACCESS   [conn850] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.130+0800 I ACCESS   [conn848] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.130+0800 I ACCESS   [conn863] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.131+0800 I ACCESS   [conn885] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.131+0800 I ACCESS   [conn913] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.131+0800 I ACCESS   [conn859] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.132+0800 I ACCESS   [conn922] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.132+0800 I ACCESS   [conn853] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.132+0800 I ACCESS   [conn899] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.132+0800 I ACCESS   [conn868] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.132+0800 I ACCESS   [conn849] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.133+0800 I ACCESS   [conn894] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.133+0800 I ACCESS   [conn921] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.133+0800 I ACCESS   [conn821] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.133+0800 I ACCESS   [conn825] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.133+0800 I ACCESS   [conn903] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.133+0800 I ACCESS   [conn927] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.134+0800 I ACCESS   [conn905] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.134+0800 I ACCESS   [conn908] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.135+0800 I ACCESS   [conn906] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.346+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55284 #929 (169 connections now open)
2016-11-23T19:42:25.374+0800 I ACCESS   [conn929] Successfully authenticated as principal __system on local
2016-11-23T19:42:25.520+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:35764 #930 (170 connections now open)
2016-11-23T19:42:25.520+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:35766 #931 (171 connections now open)
2016-11-23T19:42:25.521+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:35768 #932 (172 connections now open)
2016-11-23T19:42:25.521+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:35769 #933 (173 connections now open)
2016-11-23T19:42:25.526+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:35772 #934 (174 connections now open)
2016-11-23T19:42:25.906+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55304 #935 (175 connections now open)
2016-11-23T19:42:25.922+0800 I ACCESS   [conn935] Successfully authenticated as principal __system on local
2016-11-23T19:42:25.922+0800 I NETWORK  [conn935] end connection 172.28.0.3:55304 (174 connections now open)
2016-11-23T19:42:25.922+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55308 #936 (175 connections now open)
2016-11-23T19:42:25.922+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55306 #937 (176 connections now open)
2016-11-23T19:42:25.939+0800 I ACCESS   [conn937] Successfully authenticated as principal __system on local
2016-11-23T19:42:25.939+0800 I ACCESS   [conn936] Successfully authenticated as principal __system on local
2016-11-23T19:42:27.294+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:35884 #938 (177 connections now open)
2016-11-23T19:42:27.296+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:35886 #939 (178 connections now open)
2016-11-23T19:42:27.307+0800 I ACCESS   [conn939] Successfully authenticated as principal ceilometer on ceilometer

Comment by lei pei [ 26/Nov/16 ]

log @ 172.28.9.140

2016-11-23T19:42:24.343+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55192 #886 (126 connections now open)
2016-11-23T19:42:24.343+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55194 #887 (127 connections now open)
2016-11-23T19:42:24.343+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55196 #888 (128 connections now open)
2016-11-23T19:42:24.343+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55198 #889 (129 connections now open)
2016-11-23T19:42:24.343+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55200 #890 (130 connections now open)
2016-11-23T19:42:24.343+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55202 #891 (131 connections now open)
2016-11-23T19:42:24.343+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55204 #892 (132 connections now open)
2016-11-23T19:42:24.343+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55206 #893 (133 connections now open)
2016-11-23T19:42:24.343+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55208 #894 (134 connections now open)
2016-11-23T19:42:24.344+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55210 #895 (135 connections now open)
2016-11-23T19:42:24.344+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55212 #896 (136 connections now open)
2016-11-23T19:42:24.344+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55214 #897 (137 connections now open)
2016-11-23T19:42:24.344+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55216 #898 (138 connections now open)
2016-11-23T19:42:24.345+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55218 #899 (139 connections now open)
2016-11-23T19:42:24.345+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55220 #900 (140 connections now open)
2016-11-23T19:42:24.346+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55222 #901 (141 connections now open)
2016-11-23T19:42:24.347+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55224 #902 (142 connections now open)
2016-11-23T19:42:24.348+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55226 #903 (143 connections now open)
2016-11-23T19:42:24.348+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55228 #904 (144 connections now open)
2016-11-23T19:42:24.349+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55230 #905 (145 connections now open)
2016-11-23T19:42:24.351+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55232 #906 (146 connections now open)
2016-11-23T19:42:24.352+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55234 #907 (147 connections now open)
2016-11-23T19:42:24.352+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55236 #908 (148 connections now open)
2016-11-23T19:42:24.353+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55238 #909 (149 connections now open)
2016-11-23T19:42:24.354+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55240 #910 (150 connections now open)
2016-11-23T19:42:24.355+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55242 #911 (151 connections now open)
2016-11-23T19:42:24.355+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55244 #912 (152 connections now open)
2016-11-23T19:42:24.356+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55246 #913 (153 connections now open)
2016-11-23T19:42:24.356+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55248 #914 (154 connections now open)
2016-11-23T19:42:24.357+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55250 #915 (155 connections now open)
2016-11-23T19:42:24.358+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55252 #916 (156 connections now open)
2016-11-23T19:42:24.359+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55254 #917 (157 connections now open)
2016-11-23T19:42:24.359+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55256 #918 (158 connections now open)
2016-11-23T19:42:24.360+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55258 #919 (159 connections now open)
2016-11-23T19:42:24.360+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55260 #920 (160 connections now open)
2016-11-23T19:42:24.361+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55262 #921 (161 connections now open)
2016-11-23T19:42:24.362+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55264 #922 (162 connections now open)
2016-11-23T19:42:24.363+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55266 #923 (163 connections now open)
2016-11-23T19:42:24.363+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55268 #924 (164 connections now open)
2016-11-23T19:42:24.364+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55270 #925 (165 connections now open)
2016-11-23T19:42:24.365+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55272 #926 (166 connections now open)
2016-11-23T19:42:24.365+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55274 #927 (167 connections now open)
2016-11-23T19:42:24.366+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55276 #928 (168 connections now open)
2016-11-23T19:42:24.528+0800 I ACCESS   [conn910] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:24.543+0800 I ACCESS   [conn918] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:24.583+0800 I ACCESS   [conn830] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:24.615+0800 I ACCESS   [conn827] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:24.676+0800 I ACCESS   [conn917] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:24.699+0800 I ACCESS   [conn909] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:24.720+0800 I ASIO     [ReplicationExecutor] dropping unhealthy pooled connection to 172.28.9.141:27017
2016-11-23T19:42:24.720+0800 I ASIO     [ReplicationExecutor] after drop, pool was empty, going to spawn some connections
2016-11-23T19:42:24.720+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T19:42:24.736+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Successfully connected to 172.28.9.141:27017
2016-11-23T19:42:24.736+0800 I REPL     [ReplicationExecutor] Member 172.28.9.141:27017 is now in state ROLLBACK
2016-11-23T19:42:24.776+0800 I ACCESS   [conn818] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:24.791+0800 I ACCESS   [conn882] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:24.863+0800 I ACCESS   [conn832] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:24.924+0800 I ACCESS   [conn840] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.042+0800 I ACCESS   [conn855] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.105+0800 I ACCESS   [conn833] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.116+0800 I ACCESS   [conn858] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.116+0800 I ACCESS   [conn925] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.116+0800 I ACCESS   [conn878] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.117+0800 I ACCESS   [conn838] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.117+0800 I ACCESS   [conn883] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.117+0800 I ACCESS   [conn861] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.117+0800 I ACCESS   [conn916] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.117+0800 I ACCESS   [conn823] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.117+0800 I ACCESS   [conn856] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.117+0800 I ACCESS   [conn896] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.118+0800 I ACCESS   [conn831] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.118+0800 I ACCESS   [conn857] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.118+0800 I ACCESS   [conn920] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.118+0800 I ACCESS   [conn844] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.118+0800 I ACCESS   [conn881] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.118+0800 I ACCESS   [conn836] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:25.118+0800 I ACCESS   [conn915] Successfully authenticated as principal ceilometer on ceilometer

Comment by lei pei [ 26/Nov/16 ]

log @ 172.28.9.140

2016-11-23T19:42:23.935+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55048 #816 (57 connections now open)
2016-11-23T19:42:23.937+0800 I ACCESS   [conn814] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:23.953+0800 I ACCESS   [conn815] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:23.970+0800 I ACCESS   [conn816] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:24.003+0800 I NETWORK  [conn811] end connection 172.28.0.4:35718 (56 connections now open)
2016-11-23T19:42:24.026+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:35734 #817 (57 connections now open)
2016-11-23T19:42:24.048+0800 I ACCESS   [conn817] Successfully authenticated as principal __system on local
2016-11-23T19:42:24.305+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55056 #818 (58 connections now open)
2016-11-23T19:42:24.305+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55058 #819 (59 connections now open)
2016-11-23T19:42:24.306+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55060 #820 (60 connections now open)
2016-11-23T19:42:24.306+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55062 #821 (61 connections now open)
2016-11-23T19:42:24.309+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55064 #822 (62 connections now open)
2016-11-23T19:42:24.310+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55066 #823 (63 connections now open)
2016-11-23T19:42:24.310+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55068 #824 (64 connections now open)
2016-11-23T19:42:24.311+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55070 #825 (65 connections now open)
2016-11-23T19:42:24.311+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55072 #826 (66 connections now open)
2016-11-23T19:42:24.312+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55074 #827 (67 connections now open)
2016-11-23T19:42:24.313+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55076 #828 (68 connections now open)
2016-11-23T19:42:24.313+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55078 #829 (69 connections now open)
2016-11-23T19:42:24.314+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55080 #830 (70 connections now open)
2016-11-23T19:42:24.315+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55082 #831 (71 connections now open)
2016-11-23T19:42:24.315+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55084 #832 (72 connections now open)
2016-11-23T19:42:24.316+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55086 #833 (73 connections now open)
2016-11-23T19:42:24.317+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55088 #834 (74 connections now open)
2016-11-23T19:42:24.317+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55090 #835 (75 connections now open)
2016-11-23T19:42:24.318+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55092 #836 (76 connections now open)
2016-11-23T19:42:24.319+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55094 #837 (77 connections now open)
2016-11-23T19:42:24.320+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55096 #838 (78 connections now open)
2016-11-23T19:42:24.320+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55098 #839 (79 connections now open)
2016-11-23T19:42:24.321+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55100 #840 (80 connections now open)
2016-11-23T19:42:24.322+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55102 #841 (81 connections now open)
2016-11-23T19:42:24.322+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55104 #842 (82 connections now open)
2016-11-23T19:42:24.323+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55106 #843 (83 connections now open)
2016-11-23T19:42:24.324+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55108 #844 (84 connections now open)
2016-11-23T19:42:24.324+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55110 #845 (85 connections now open)
2016-11-23T19:42:24.325+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55112 #846 (86 connections now open)
2016-11-23T19:42:24.326+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55114 #847 (87 connections now open)
2016-11-23T19:42:24.326+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55116 #848 (88 connections now open)
2016-11-23T19:42:24.327+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55118 #849 (89 connections now open)
2016-11-23T19:42:24.328+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55120 #850 (90 connections now open)
2016-11-23T19:42:24.328+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55122 #851 (91 connections now open)
2016-11-23T19:42:24.329+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55124 #852 (92 connections now open)
2016-11-23T19:42:24.330+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55126 #853 (93 connections now open)
2016-11-23T19:42:24.330+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55128 #854 (94 connections now open)
2016-11-23T19:42:24.331+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55130 #855 (95 connections now open)
2016-11-23T19:42:24.332+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55132 #856 (96 connections now open)
2016-11-23T19:42:24.332+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55134 #857 (97 connections now open)
2016-11-23T19:42:24.333+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55136 #858 (98 connections now open)
2016-11-23T19:42:24.334+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55138 #859 (99 connections now open)
2016-11-23T19:42:24.334+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55140 #860 (100 connections now open)
2016-11-23T19:42:24.335+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55142 #861 (101 connections now open)
2016-11-23T19:42:24.336+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55144 #862 (102 connections now open)
2016-11-23T19:42:24.336+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55146 #863 (103 connections now open)
2016-11-23T19:42:24.337+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55148 #864 (104 connections now open)
2016-11-23T19:42:24.337+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55150 #865 (105 connections now open)
2016-11-23T19:42:24.338+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55152 #866 (106 connections now open)
2016-11-23T19:42:24.338+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55154 #867 (107 connections now open)
2016-11-23T19:42:24.338+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55156 #868 (108 connections now open)
2016-11-23T19:42:24.338+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55158 #869 (109 connections now open)
2016-11-23T19:42:24.338+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55160 #870 (110 connections now open)
2016-11-23T19:42:24.338+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55162 #871 (111 connections now open)
2016-11-23T19:42:24.338+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55164 #872 (112 connections now open)
2016-11-23T19:42:24.338+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55166 #873 (113 connections now open)
2016-11-23T19:42:24.338+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55168 #874 (114 connections now open)
2016-11-23T19:42:24.338+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55170 #875 (115 connections now open)
2016-11-23T19:42:24.338+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55172 #876 (116 connections now open)
2016-11-23T19:42:24.339+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55174 #877 (117 connections now open)
2016-11-23T19:42:24.339+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55176 #878 (118 connections now open)
2016-11-23T19:42:24.339+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55178 #879 (119 connections now open)
2016-11-23T19:42:24.339+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55180 #880 (120 connections now open)
2016-11-23T19:42:24.339+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55182 #881 (121 connections now open)
2016-11-23T19:42:24.340+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55184 #882 (122 connections now open)
2016-11-23T19:42:24.341+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55186 #883 (123 connections now open)
2016-11-23T19:42:24.341+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55188 #884 (124 connections now open)
2016-11-23T19:42:24.342+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55190 #885 (125 connections now open)
2016-11-23T19:42:24.343+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55192 #886 (126 connections now open)
2016-11-23T19:42:24.343+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:55194 #887 (127 connections now open)

Comment by lei pei [ 26/Nov/16 ]

log @172.28.9.140

2016-11-23T19:42:20.852+0800 I REPL [ReplicationExecutor] Error in heartbeat request to 172.28.9.142:27017; HostUnreachable: No route to host
2016-11-23T19:42:20.852+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.142:27017
2016-11-23T19:42:21.080+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.141:27017 - HostUnreachable: No route to host
2016-11-23T19:42:21.080+0800 I REPL [ReplicationExecutor] Error in heartbeat request to 172.28.9.141:27017; HostUnreachable: No route to host
2016-11-23T19:42:21.080+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T19:42:21.869+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Successfully connected to 172.28.9.142:27017
2016-11-23T19:42:21.870+0800 I REPL [ReplicationExecutor] Member 172.28.9.142:27017 is now in state SECONDARY
2016-11-23T19:42:22.097+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Successfully connected to 172.28.9.141:27017
2016-11-23T19:42:22.097+0800 I REPL [ReplicationExecutor] Member 172.28.9.141:27017 is now in state SECONDARY
2016-11-23T19:42:22.350+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.3:53752 #784 (26 connections now open)
2016-11-23T19:42:22.525+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.4:35090 #785 (27 connections now open)
2016-11-23T19:42:22.525+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.4:35098 #786 (28 connections now open)
2016-11-23T19:42:22.525+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.4:35100 #787 (29 connections now open)
2016-11-23T19:42:22.525+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.4:35096 #788 (30 connections now open)
2016-11-23T19:42:22.525+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.4:35104 #789 (31 connections now open)
2016-11-23T19:42:22.699+0800 I REPL [ReplicationExecutor] Starting an election, since we've seen no PRIMARY in the past 10000ms
2016-11-23T19:42:22.699+0800 I REPL [ReplicationExecutor] conducting a dry run election to see if we could be elected
2016-11-23T19:42:22.700+0800 I REPL [ReplicationExecutor] VoteRequester: Got no vote from 172.28.9.141:27017 because: candidate's data is staler than mine, resp:

{ term: 8, voteGranted: false, reason: "candidate's data is staler than mine", ok: 1.0 }

2016-11-23T19:42:22.700+0800 I REPL [ReplicationExecutor] dry election run succeeded, running for election
2016-11-23T19:42:22.719+0800 I REPL [ReplicationExecutor] VoteRequester: Got no vote from 172.28.9.141:27017 because: candidate's data is staler than mine, resp:

{ term: 9, voteGranted: false, reason: "candidate's data is staler than mine", ok: 1.0 }

2016-11-23T19:42:22.719+0800 I REPL [ReplicationExecutor] election succeeded, assuming primary role in term 9
2016-11-23T19:42:22.719+0800 I REPL [ReplicationExecutor] transition to PRIMARY
2016-11-23T19:42:22.902+0800 I REPL [rsSync] transition to primary complete; database writes are now permitted
2016-11-23T19:42:23.345+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.2:58764 #790 (32 connections now open)
2016-11-23T19:42:23.370+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.3:54600 #791 (33 connections now open)
2016-11-23T19:42:23.404+0800 I ACCESS [conn790] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:23.405+0800 I ACCESS [conn791] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:23.513+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.3:54730 #792 (34 connections now open)
2016-11-23T19:42:23.515+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.3:54738 #793 (35 connections now open)
2016-11-23T19:42:23.516+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.4:35710 #794 (36 connections now open)
2016-11-23T19:42:23.525+0800 I ACCESS [conn793] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:23.534+0800 I ACCESS [conn794] Successfully authenticated as principal __system on local
2016-11-23T19:42:23.548+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.2:58902 #795 (37 connections now open)
2016-11-23T19:42:23.551+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.2:58910 #796 (38 connections now open)
2016-11-23T19:42:23.561+0800 I ACCESS [conn796] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:23.607+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.3:54822 #797 (39 connections now open)
2016-11-23T19:42:23.609+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.3:54826 #798 (40 connections now open)
2016-11-23T19:42:23.621+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.3:54836 #799 (41 connections now open)
2016-11-23T19:42:23.621+0800 I ACCESS [conn797] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:23.632+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.3:54848 #800 (42 connections now open)
2016-11-23T19:42:23.640+0800 I ACCESS [conn798] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:23.642+0800 I ACCESS [conn799] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:23.644+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.3:54860 #801 (43 connections now open)
2016-11-23T19:42:23.645+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.2:58988 #802 (44 connections now open)
2016-11-23T19:42:23.647+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.2:58990 #803 (45 connections now open)
2016-11-23T19:42:23.655+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.3:54868 #804 (46 connections now open)
2016-11-23T19:42:23.656+0800 I ACCESS [conn800] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:23.656+0800 I ACCESS [conn802] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:23.659+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.3:54874 #805 (47 connections now open)
2016-11-23T19:42:23.659+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.2:58992 #806 (48 connections now open)
2016-11-23T19:42:23.669+0800 I ACCESS [conn803] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:23.669+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.2:58994 #807 (49 connections now open)
2016-11-23T19:42:23.675+0800 I ACCESS [conn801] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:23.677+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.3:54890 #808 (50 connections now open)
2016-11-23T19:42:23.678+0800 I ACCESS [conn804] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:23.679+0800 I ACCESS [conn806] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:23.681+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.2:58996 #809 (51 connections now open)
2016-11-23T19:42:23.692+0800 I ACCESS [conn807] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:23.706+0800 I ACCESS [conn809] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:23.709+0800 I ACCESS [conn805] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:23.713+0800 I ACCESS [conn808] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:23.859+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.4:35716 #810 (52 connections now open)
2016-11-23T19:42:23.875+0800 I ACCESS [conn810] Successfully authenticated as principal __system on local
2016-11-23T19:42:23.875+0800 I NETWORK [conn810] end connection 172.28.0.4:35716 (51 connections now open)
2016-11-23T19:42:23.876+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.4:35718 #811 (52 connections now open)
2016-11-23T19:42:23.876+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.4:35720 #812 (53 connections now open)
2016-11-23T19:42:23.894+0800 I ACCESS [conn812] Successfully authenticated as principal __system on local
2016-11-23T19:42:23.894+0800 I ACCESS [conn811] Successfully authenticated as principal __system on local
2016-11-23T19:42:23.913+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.3:55042 #813 (54 connections now open)
2016-11-23T19:42:23.915+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.3:55044 #814 (55 connections now open)
2016-11-23T19:42:23.925+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.3:55046 #815 (56 connections now open)
2016-11-23T19:42:23.925+0800 I ACCESS [conn813] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:23.935+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.3:55048 #816 (57 connections now open)
2016-11-23T19:42:23.937+0800 I ACCESS [conn814] Successfully authenticated as principal ceilometer on ceilometer

Comment by lei pei [ 26/Nov/16 ]

log @ 172.28.9.140

2016-11-23T15:02:07.818+0800 I NETWORK [conn104] end connection 172.28.0.2:52208 (81 connections now open)
2016-11-23T15:02:27.442+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.2:52386 #105 (82 connections now open)
2016-11-23T15:02:27.443+0800 I ACCESS [conn105] Unauthorized: not authorized on admin to execute command

{ replSetGetStatus: 1.0, forShell: 1.0 }

2016-11-23T15:02:27.464+0800 I ACCESS [conn105] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T15:02:27.466+0800 I NETWORK [conn105] end connection 172.28.0.2:52386 (81 connections now open)
2016-11-23T15:07:11.936+0800 I CONTROL [main] ***** SERVER RESTARTED *****
2016-11-23T15:07:12.224+0800 I CONTROL [initandlisten] MongoDB starting : pid=19174 port=27017 dbpath=/var/ceilometer 64-bit host=FirstNode
2016-11-23T15:07:12.224+0800 I CONTROL [initandlisten] db version v3.2.10
2016-11-23T15:07:12.224+0800 I CONTROL [initandlisten] git version: ed70e33130c977bda0024c125b56d159573dbaf0
2016-11-23T15:07:12.224+0800 I CONTROL [initandlisten] OpenSSL version: OpenSSL 1.0.1e-fips 11 Feb 2013
2016-11-23T15:07:12.224+0800 I CONTROL [initandlisten] allocator: tcmalloc
2016-11-23T15:07:12.224+0800 I CONTROL [initandlisten] modules: none
2016-11-23T15:07:12.224+0800 I CONTROL [initandlisten] build environment:
2016-11-23T15:07:12.224+0800 I CONTROL [initandlisten] distarch: x86_64
2016-11-23T15:07:12.224+0800 I CONTROL [initandlisten] target_arch: x86_64
2016-11-23T15:07:12.224+0800 I CONTROL [initandlisten] options: { config: "/etc/mongodb/mongodb.conf", net:

{ bindIp: "172.28.9.140" }

, processManagement:

{ fork: true }

, replication:

{ oplogSizeMB: 3072, replSet: "fsp" }

, security:

{ authorization: "enabled", keyFile: "/etc/mongodb/mongodb-keyfile" }

, storage: { dbPath: "/var/ceilometer", mmapv1:

{ smallFiles: true }

}, systemLog:

{ destination: "file", logAppend: true, path: "/var/log/fusionsphere/component/mongodb/mongodb.log" }

}
2016-11-23T15:07:12.257+0800 I - [initandlisten] Detected data files in /var/ceilometer created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2016-11-23T15:07:12.257+0800 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=36G,session_max=20000,eviction=(threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0),
2016-11-23T15:07:19.201+0800 I STORAGE [initandlisten] Starting WiredTigerRecordStoreThread local.oplog.rs
2016-11-23T15:07:19.201+0800 I STORAGE [initandlisten] The size storer reports that the oplog contains 476229 records totaling to 360688534 bytes
2016-11-23T15:07:19.244+0800 I STORAGE [initandlisten] Sampling from the oplog between Nov 21 13:04:26:1 and Nov 23 15:02:15:c to determine where to place markers for truncation
2016-11-23T15:07:19.244+0800 I STORAGE [initandlisten] Taking 111 samples and assuming that each section of oplog contains approximately 42531 records totaling to 32212326 bytes
2016-11-23T15:07:24.360+0800 I STORAGE [initandlisten] Placing a marker at optime Nov 22 00:24:24:8
2016-11-23T15:07:24.360+0800 I STORAGE [initandlisten] Placing a marker at optime Nov 22 07:12:23:42
2016-11-23T15:07:24.360+0800 I STORAGE [initandlisten] Placing a marker at optime Nov 22 10:36:00:1e
2016-11-23T15:07:24.360+0800 I STORAGE [initandlisten] Placing a marker at optime Nov 22 12:52:23:2
2016-11-23T15:07:24.360+0800 I STORAGE [initandlisten] Placing a marker at optime Nov 22 16:26:52:1b
2016-11-23T15:07:24.360+0800 I STORAGE [initandlisten] Placing a marker at optime Nov 22 20:44:04:3
2016-11-23T15:07:24.360+0800 I STORAGE [initandlisten] Placing a marker at optime Nov 23 00:05:50:5a
2016-11-23T15:07:24.360+0800 I STORAGE [initandlisten] Placing a marker at optime Nov 23 03:49:12:1c
2016-11-23T15:07:24.360+0800 I STORAGE [initandlisten] Placing a marker at optime Nov 23 07:31:03:5e
2016-11-23T15:07:24.360+0800 I STORAGE [initandlisten] Placing a marker at optime Nov 23 11:17:15:5
2016-11-23T15:07:24.360+0800 I STORAGE [initandlisten] Placing a marker at optime Nov 23 14:44:01:50
2016-11-23T15:07:24.490+0800 W STORAGE [initandlisten] Detected configuration for non-active storage engine mmapv1 when current storage engine is wiredTiger
2016-11-23T15:07:24.491+0800 I CONTROL [initandlisten]
2016-11-23T15:07:24.491+0800 I CONTROL [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/enabled is 'always'.
2016-11-23T15:07:24.491+0800 I CONTROL [initandlisten] ** We suggest setting it to 'never'
2016-11-23T15:07:24.491+0800 I CONTROL [initandlisten]
2016-11-23T15:07:24.491+0800 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. The locked memory size is 32768 bytes, it should be at least 65536 bytes
2016-11-23T15:07:24.491+0800 I CONTROL [initandlisten]
2016-11-23T15:07:24.491+0800 I CONTROL [initandlisten] ** WARNING: soft rlimits too low. rlimits set to 16384 processes, 65536 files. Number of processes should be at least 32768 : 0.5 times number of files.
2016-11-23T15:07:24.491+0800 I CONTROL [initandlisten]
2016-11-23T15:07:24.656+0800 I NETWORK [HostnameCanonicalizationWorker] Starting hostname canonicalization worker
2016-11-23T15:07:24.656+0800 I FTDC [initandlisten] Initializing full-time diagnostic data capture with directory '/var/ceilometer/diagnostic.data'
2016-11-23T15:07:24.676+0800 I NETWORK [initandlisten] waiting for connections on port 27017
2016-11-23T15:07:24.706+0800 I REPL [ReplicationExecutor] New replica set config in use: { _id: "fsp", version: 1, protocolVersion: 1, members: [ { _id: 0, host: "172.28.9.140:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 1, host: "172.28.9.141:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 2, host: "172.28.9.142:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 } ], settings: { chainingAllowed: true, heartbeatIntervalMillis: 2000, heartbeatTimeoutSecs: 10, electionTimeoutMillis: 10000, getLastErrorModes: {}, getLastErrorDefaults:

{ w: 1, wtimeout: 0 }

, replicaSetId: ObjectId('5832805a9e60d600d0a351d0') } }
2016-11-23T15:07:24.706+0800 I REPL [ReplicationExecutor] This node is 172.28.9.140:27017 in the config
2016-11-23T15:07:24.706+0800 I REPL [ReplicationExecutor] transition to STARTUP2
2016-11-23T15:07:24.706+0800 I REPL [ReplicationExecutor] Starting replication applier threads
2016-11-23T15:07:24.706+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T15:07:24.706+0800 I REPL [ReplicationExecutor] transition to RECOVERING
2016-11-23T15:07:24.706+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.142:27017
2016-11-23T15:07:24.714+0800 I REPL [ReplicationExecutor] transition to SECONDARY
2016-11-23T15:07:24.734+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Successfully connected to 172.28.9.141:27017
2016-11-23T15:07:24.734+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Successfully connected to 172.28.9.142:27017
2016-11-23T15:07:24.734+0800 I REPL [ReplicationExecutor] Member 172.28.9.141:27017 is now in state PRIMARY
2016-11-23T15:07:24.734+0800 I REPL [ReplicationExecutor] Member 172.28.9.142:27017 is now in state SECONDARY
2016-11-23T15:07:24.790+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.4:37950 #1 (1 connection now open)
2016-11-23T15:07:24.815+0800 I ACCESS [conn1] Successfully authenticated as principal __system on local
2016-11-23T15:07:25.019+0800 I FTDC [ftdc] Unclean full-time diagnostic data capture shutdown detected, found interim file, some metrics may have been lost. OK
2016-11-23T15:07:26.539+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.3:50314 #2 (2 connections now open)
2016-11-23T15:07:26.556+0800 I ACCESS [conn2] Successfully authenticated as principal __system on local

Comment by lei pei [ 26/Nov/16 ]

log @ 172.28.9.142
2016-11-23T19:42:31.210+0800 I NETWORK [conn1687] end connection 172.28.0.4:41216 (80 connections now open)
2016-11-23T19:42:31.524+0800 I ASIO [ReplicationExecutor] dropping unhealthy pooled connection to 172.28.9.141:27017
2016-11-23T19:42:31.524+0800 I ASIO [ReplicationExecutor] after drop, pool was empty, going to spawn some connections
2016-11-23T19:42:31.524+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T19:42:31.524+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.141:27017 - HostUnreachable: Connection refused
2016-11-23T19:42:31.525+0800 I REPL [ReplicationExecutor] Error in heartbeat request to 172.28.9.141:27017; HostUnreachable: Connection refused
2016-11-23T19:42:31.525+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T19:42:31.525+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.141:27017 - HostUnreachable: Connection refused
2016-11-23T19:42:31.525+0800 I REPL [ReplicationExecutor] Error in heartbeat request to 172.28.9.141:27017; HostUnreachable: Connection refused
2016-11-23T19:42:31.525+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T19:42:31.525+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.141:27017 - HostUnreachable: Connection refused
2016-11-23T19:42:31.525+0800 I REPL [ReplicationExecutor] Error in heartbeat request to 172.28.9.141:27017; HostUnreachable: Connection refused
2016-11-23T19:42:33.525+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T19:42:33.526+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.141:27017 - HostUnreachable: Connection refused
2016-11-23T19:42:33.526+0800 I REPL [ReplicationExecutor] Error in heartbeat request to 172.28.9.141:27017; HostUnreachable: Connection refused
2016-11-23T19:42:33.526+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T19:42:33.526+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.141:27017 - HostUnreachable: Connection refused
2016-11-23T19:42:33.526+0800 I REPL [ReplicationExecutor] Error in heartbeat request to 172.28.9.141:27017; HostUnreachable: Connection refused
2016-11-23T19:42:33.526+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T19:42:33.526+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.141:27017 - HostUnreachable: Connection refused
2016-11-23T19:42:33.526+0800 I REPL [ReplicationExecutor] Error in heartbeat request to 172.28.9.141:27017; HostUnreachable: Connection refused
2016-11-23T19:42:34.593+0800 I NETWORK [initandlisten] connection accepted from 172.28.0.3:32954 #1741 (81 connections now open)
2016-11-23T19:42:34.594+0800 I ACCESS [conn1741] Unauthorized: not authorized on admin to execute command

{ replSetGetStatus: 1.0, forShell: 1.0 }

2016-11-23T19:42:34.614+0800 I ACCESS [conn1741] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T19:42:34.618+0800 I NETWORK [conn1741] end connection 172.28.0.3:32954 (80 connections now open)
2016-11-23T19:42:35.526+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T19:42:35.527+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.141:27017 - HostUnreachable: Connection refused
2016-11-23T19:42:35.527+0800 I REPL [ReplicationExecutor] Error in heartbeat request to 172.28.9.141:27017; HostUnreachable: Connection refused
2016-11-23T19:42:35.527+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T19:42:35.527+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.141:27017 - HostUnreachable: Connection refused
2016-11-23T19:42:35.527+0800 I REPL [ReplicationExecutor] Error in heartbeat request to 172.28.9.141:27017; HostUnreachable: Connection refused
2016-11-23T19:42:35.527+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T19:42:35.527+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.141:27017 - HostUnreachable: Connection refused
2016-11-23T19:42:35.527+0800 I REPL [ReplicationExecutor] Error in heartbeat request to 172.28.9.141:27017; HostUnreachable: Connection refused
2016-11-23T19:42:37.527+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T19:42:37.527+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.141:27017 - HostUnreachable: Connection refused
2016-11-23T19:42:37.527+0800 I REPL [ReplicationExecutor] Error in heartbeat request to 172.28.9.141:27017; HostUnreachable: Connection refused
2016-11-23T19:42:37.527+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T19:42:37.527+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.141:27017 - HostUnreachable: Connection refused
2016-11-23T19:42:37.527+0800 I REPL [ReplicationExecutor] Error in heartbeat request to 172.28.9.141:27017; HostUnreachable: Connection refused
2016-11-23T19:42:37.528+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T19:42:37.528+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.141:27017 - HostUnreachable: Connection refused
2016-11-23T19:42:37.528+0800 I REPL [ReplicationExecutor] Error in heartbeat request to 172.28.9.141:27017; HostUnreachable: Connection refused
2016-11-23T19:42:39.528+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T19:42:39.528+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.141:27017 - HostUnreachable: Connection refused
2016-11-23T19:42:39.528+0800 I REPL [ReplicationExecutor] Error in heartbeat request to 172.28.9.141:27017; HostUnreachable: Connection refused
2016-11-23T19:42:39.528+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T19:42:39.528+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.141:27017 - HostUnreachable: Connection refused
2016-11-23T19:42:39.528+0800 I REPL [ReplicationExecutor] Error in heartbeat request to 172.28.9.141:27017; HostUnreachable: Connection refused
2016-11-23T19:42:39.528+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T19:42:39.528+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.141:27017 - HostUnreachable: Connection refused
2016-11-23T19:42:39.528+0800 I REPL [ReplicationExecutor] Error in heartbeat request to 172.28.9.141:27017; HostUnreachable: Connection refused
2016-11-23T19:42:41.528+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T19:42:41.528+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.141:27017 - HostUnreachable: Connection refused
2016-11-23T19:42:41.528+0800 I REPL [ReplicationExecutor] Error in heartbeat request to 172.28.9.141:27017; HostUnreachable: Connection refused
2016-11-23T19:42:41.528+0800 I ASIO [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017

Comment by lei pei [ 26/Nov/16 ]

log @ 172.27.9.142

2016-11-23T19:42:21.912+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:48716 #1685 (26 connections now open)
2016-11-23T19:42:21.912+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:48724 #1686 (27 connections now open)
2016-11-23T19:42:21.927+0800 I ACCESS   [conn1685] Successfully authenticated as principal __system on local
2016-11-23T19:42:22.062+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:41216 #1687 (28 connections now open)
2016-11-23T19:42:22.081+0800 I ACCESS   [conn1687] Successfully authenticated as principal __system on local
2016-11-23T19:42:22.321+0800 I REPL     [ReplicationExecutor] Not starting an election, since we are not electable
2016-11-23T19:42:23.572+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:60382 #1688 (29 connections now open)
2016-11-23T19:42:23.607+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:49656 #1689 (30 connections now open)
2016-11-23T19:42:24.507+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T19:42:24.523+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Successfully connected to 172.28.9.141:27017
2016-11-23T19:42:24.523+0800 I REPL     [ReplicationExecutor] Member 172.28.9.141:27017 is now in state ROLLBACK
2016-11-23T19:42:25.404+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.140:27017
2016-11-23T19:42:25.432+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Successfully connected to 172.28.9.140:27017
2016-11-23T19:42:25.432+0800 I REPL     [ReplicationExecutor] Member 172.28.9.140:27017 is now in state PRIMARY
2016-11-23T19:42:25.964+0800 I REPL     [ReplicationExecutor] syncing from: 172.28.9.140:27017
2016-11-23T19:42:25.980+0800 I REPL     [SyncSourceFeedback] setting syncSourceFeedback to 172.28.9.140:27017
2016-11-23T19:42:25.980+0800 I ASIO     [NetworkInterfaceASIO-BGSync-0] Connecting to 172.28.9.140:27017
2016-11-23T19:42:25.996+0800 I ASIO     [NetworkInterfaceASIO-BGSync-0] Successfully connected to 172.28.9.140:27017
2016-11-23T19:42:27.364+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42274 #1690 (31 connections now open)
2016-11-23T19:42:27.364+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42276 #1691 (32 connections now open)
2016-11-23T19:42:27.365+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42278 #1692 (33 connections now open)
2016-11-23T19:42:27.367+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42280 #1693 (34 connections now open)
2016-11-23T19:42:27.374+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42286 #1694 (35 connections now open)
2016-11-23T19:42:27.419+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42308 #1695 (36 connections now open)
2016-11-23T19:42:27.425+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42316 #1696 (37 connections now open)
2016-11-23T19:42:27.427+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42324 #1697 (38 connections now open)
2016-11-23T19:42:27.696+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42386 #1698 (39 connections now open)
2016-11-23T19:42:27.699+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42390 #1699 (40 connections now open)
2016-11-23T19:42:27.721+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42406 #1700 (41 connections now open)
2016-11-23T19:42:27.725+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42416 #1701 (42 connections now open)
2016-11-23T19:42:27.725+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42418 #1702 (43 connections now open)
2016-11-23T19:42:27.737+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42430 #1703 (44 connections now open)
2016-11-23T19:42:27.907+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:49878 #1704 (45 connections now open)
2016-11-23T19:42:27.907+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:49880 #1705 (46 connections now open)
2016-11-23T19:42:27.909+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:49882 #1706 (47 connections now open)
2016-11-23T19:42:27.909+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:49886 #1707 (48 connections now open)
2016-11-23T19:42:27.909+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:49884 #1708 (49 connections now open)
2016-11-23T19:42:27.909+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:49888 #1709 (50 connections now open)
2016-11-23T19:42:27.910+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:49890 #1710 (51 connections now open)
2016-11-23T19:42:27.910+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:49892 #1711 (52 connections now open)
2016-11-23T19:42:27.912+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:49894 #1712 (53 connections now open)
2016-11-23T19:42:27.912+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:49896 #1713 (54 connections now open)
2016-11-23T19:42:27.913+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:49898 #1714 (55 connections now open)
2016-11-23T19:42:27.913+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:49900 #1715 (56 connections now open)
2016-11-23T19:42:27.913+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:49902 #1716 (57 connections now open)
2016-11-23T19:42:27.913+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:49904 #1717 (58 connections now open)
2016-11-23T19:42:27.914+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:49906 #1718 (59 connections now open)
2016-11-23T19:42:27.915+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:49908 #1719 (60 connections now open)
2016-11-23T19:42:27.915+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:49910 #1720 (61 connections now open)
2016-11-23T19:42:27.915+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:49912 #1721 (62 connections now open)
2016-11-23T19:42:27.915+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:49914 #1722 (63 connections now open)
2016-11-23T19:42:27.917+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:49916 #1723 (64 connections now open)
2016-11-23T19:42:27.918+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:49918 #1724 (65 connections now open)
2016-11-23T19:42:27.919+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:49920 #1725 (66 connections now open)
2016-11-23T19:42:27.928+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:49922 #1726 (67 connections now open)
2016-11-23T19:42:27.928+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:49924 #1727 (68 connections now open)
2016-11-23T19:42:28.064+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42468 #1728 (69 connections now open)
2016-11-23T19:42:28.269+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42478 #1729 (70 connections now open)
2016-11-23T19:42:28.278+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42482 #1730 (71 connections now open)
2016-11-23T19:42:31.067+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42694 #1731 (72 connections now open)
2016-11-23T19:42:31.069+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42696 #1732 (73 connections now open)
2016-11-23T19:42:31.071+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42698 #1733 (74 connections now open)
2016-11-23T19:42:31.071+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42700 #1734 (75 connections now open)
2016-11-23T19:42:31.072+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42702 #1735 (76 connections now open)
2016-11-23T19:42:31.072+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42704 #1736 (77 connections now open)
2016-11-23T19:42:31.072+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42706 #1737 (78 connections now open)
2016-11-23T19:42:31.072+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42708 #1738 (79 connections now open)
2016-11-23T19:42:31.072+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42710 #1739 (80 connections now open)
2016-11-23T19:42:31.073+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:42712 #1740 (81 connections now open)
2016-11-23T19:42:31.210+0800 I NETWORK  [conn1687] end connection 172.28.0.4:41216 (80 connections now open)
2016-11-23T19:42:31.524+0800 I ASIO     [ReplicationExecutor] dropping unhealthy pooled connection to 172.28.9.141:27017
2016-11-23T19:42:31.524+0800 I ASIO     [ReplicationExecutor] after drop, pool was empty, going to spawn some connections
2016-11-23T19:42:31.524+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T19:42:31.524+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.141:27017 - HostUnreachable: Connection refused
2016-11-23T19:42:31.525+0800 I REPL     [ReplicationExecutor] Error in heartbeat request to 172.28.9.141:27017; HostUnreachable: Connection refused

Comment by lei pei [ 26/Nov/16 ]

log @ 172.28.9.142:

2016-11-23T03:15:27.634+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Successfully connected to 172.28.9.141:27017
2016-11-23T03:15:27.635+0800 I REPL     [ReplicationExecutor] Member 172.28.9.141:27017 is now in state SECONDARY
2016-11-23T03:15:36.513+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:51528 #74 (73 connections now open)
2016-11-23T03:15:36.515+0800 I ACCESS   [conn74] Unauthorized: not authorized on admin to execute command { replSetGetStatus: 1.0, forShell: 1.0 }
2016-11-23T03:15:36.534+0800 I ACCESS   [conn74] Successfully authenticated as principal ceilometer on ceilometer
2016-11-23T03:15:36.537+0800 I NETWORK  [conn74] end connection 172.28.0.3:51528 (72 connections now open)
2016-11-23T11:20:12.907+0800 I CONTROL  [main] ***** SERVER RESTARTED *****
2016-11-23T11:20:13.160+0800 I CONTROL  [initandlisten] MongoDB starting : pid=19069 port=27017 dbpath=/var/ceilometer 64-bit host=28B4A688-1DD2-11B2-BFBC-0018E1C5D866
2016-11-23T11:20:13.160+0800 I CONTROL  [initandlisten] db version v3.2.10
2016-11-23T11:20:13.160+0800 I CONTROL  [initandlisten] git version: ed70e33130c977bda0024c125b56d159573dbaf0
2016-11-23T11:20:13.160+0800 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.0.1e-fips 11 Feb 2013
2016-11-23T11:20:13.160+0800 I CONTROL  [initandlisten] allocator: tcmalloc
2016-11-23T11:20:13.160+0800 I CONTROL  [initandlisten] modules: none
2016-11-23T11:20:13.160+0800 I CONTROL  [initandlisten] build environment:
2016-11-23T11:20:13.160+0800 I CONTROL  [initandlisten]     distarch: x86_64
2016-11-23T11:20:13.160+0800 I CONTROL  [initandlisten]     target_arch: x86_64
2016-11-23T11:20:13.160+0800 I CONTROL  [initandlisten] options: { config: "/etc/mongodb/mongodb.conf", net: { bindIp: "172.28.9.142" }, processManagement: { fork: true }, replication: { oplogSizeMB: 3072, replSet: "fsp" }, security: { authorization: "enabled", keyFile: "/etc/mongodb/mongodb-keyfile" }, storage: { dbPath: "/var/ceilometer", mmapv1: { smallFiles: true } }, systemLog: { destination: "file", logAppend: true, path: "/var/log/fusionsphere/component/mongodb/mongodb.log" } }
2016-11-23T11:20:13.204+0800 I -        [initandlisten] Detected data files in /var/ceilometer created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2016-11-23T11:20:13.204+0800 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=36G,session_max=20000,eviction=(threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0),
2016-11-23T11:20:20.650+0800 I STORAGE  [initandlisten] Starting WiredTigerRecordStoreThread local.oplog.rs
2016-11-23T11:20:20.650+0800 I STORAGE  [initandlisten] The size storer reports that the oplog contains 165795 records totaling to 143563085 bytes
2016-11-23T11:20:20.825+0800 I STORAGE  [initandlisten] Sampling from the oplog between Nov 22 20:22:50:b and Nov 23 11:15:25:30 to determine where to place markers for truncation
2016-11-23T11:20:20.825+0800 I STORAGE  [initandlisten] Taking 44 samples and assuming that each section of oplog contains approximately 37201 records totaling to 32212613 bytes
2016-11-23T11:20:22.983+0800 I STORAGE  [initandlisten] Placing a marker at optime Nov 22 23:05:49:35
2016-11-23T11:20:22.983+0800 I STORAGE  [initandlisten] Placing a marker at optime Nov 23 02:03:33:1f
2016-11-23T11:20:22.983+0800 I STORAGE  [initandlisten] Placing a marker at optime Nov 23 05:43:26:17
2016-11-23T11:20:22.983+0800 I STORAGE  [initandlisten] Placing a marker at optime Nov 23 09:24:08:a
2016-11-23T11:20:23.050+0800 W STORAGE  [initandlisten] Detected configuration for non-active storage engine mmapv1 when current storage engine is wiredTiger
2016-11-23T11:20:23.051+0800 I CONTROL  [initandlisten]
2016-11-23T11:20:23.051+0800 I CONTROL  [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/enabled is 'always'.
2016-11-23T11:20:23.051+0800 I CONTROL  [initandlisten] **        We suggest setting it to 'never'
2016-11-23T11:20:23.051+0800 I CONTROL  [initandlisten]
2016-11-23T11:20:23.051+0800 I CONTROL  [initandlisten] ** WARNING: soft rlimits too low. The locked memory size is 32768 bytes, it should be at least 65536 bytes
2016-11-23T11:20:23.051+0800 I CONTROL  [initandlisten]
2016-11-23T11:20:23.051+0800 I CONTROL  [initandlisten] ** WARNING: soft rlimits too low. rlimits set to 16384 processes, 65536 files. Number of processes should be at least 32768 : 0.5 times number of files.
2016-11-23T11:20:23.051+0800 I CONTROL  [initandlisten]
2016-11-23T11:20:23.291+0800 I NETWORK  [HostnameCanonicalizationWorker] Starting hostname canonicalization worker
2016-11-23T11:20:23.291+0800 I FTDC     [initandlisten] Initializing full-time diagnostic data capture with directory '/var/ceilometer/diagnostic.data'
2016-11-23T11:20:23.332+0800 I NETWORK  [initandlisten] waiting for connections on port 27017
2016-11-23T11:20:23.378+0800 I REPL     [ReplicationExecutor] New replica set config in use: { _id: "fsp", version: 1, protocolVersion: 1, members: [ { _id: 0, host: "172.28.9.140:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 1, host: "172.28.9.141:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 2, host: "172.28.9.142:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 } ], settings: { chainingAllowed: true, heartbeatIntervalMillis: 2000, heartbeatTimeoutSecs: 10, electionTimeoutMillis: 10000, getLastErrorModes: {}, getLastErrorDefaults: { w: 1, wtimeout: 0 }, replicaSetId: ObjectId('5832805a9e60d600d0a351d0') } }
2016-11-23T11:20:23.378+0800 I REPL     [ReplicationExecutor] This node is 172.28.9.142:27017 in the config
2016-11-23T11:20:23.378+0800 I REPL     [ReplicationExecutor] transition to STARTUP2
2016-11-23T11:20:23.378+0800 I REPL     [ReplicationExecutor] Starting replication applier threads
2016-11-23T11:20:23.415+0800 I REPL     [ReplicationExecutor] transition to RECOVERING
2016-11-23T11:20:23.415+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.140:27017
2016-11-23T11:20:23.415+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.141:27017
2016-11-23T11:20:23.424+0800 I REPL     [ReplicationExecutor] transition to SECONDARY
2016-11-23T11:20:23.432+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Successfully connected to 172.28.9.141:27017
2016-11-23T11:20:23.474+0800 I REPL     [ReplicationExecutor] Member 172.28.9.141:27017 is now in state PRIMARY
2016-11-23T11:20:23.474+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Successfully connected to 172.28.9.140:27017
2016-11-23T11:20:23.506+0800 I REPL     [ReplicationExecutor] Member 172.28.9.140:27017 is now in state SECONDARY
2016-11-23T11:20:25.012+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:57208 #1 (1 connection now open)
2016-11-23T11:20:25.050+0800 I ACCESS   [conn1] Successfully authenticated as principal __system on local
2016-11-23T11:20:25.244+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:49232 #2 (2 connections now open)
2016-11-23T11:20:25.259+0800 I ACCESS   [conn2] Successfully authenticated as principal __system on local
2016-11-23T11:20:27.649+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:54624 #3 (3 connections now open)
2016-11-23T11:20:27.998+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:49264 #4 (4 connections now open)
2016-11-23T11:20:28.126+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:49268 #5 (5 connections now open)
2016-11-23T11:20:28.126+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:49272 #6 (6 connections now open)
2016-11-23T11:20:28.126+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:49270 #7 (7 connections now open)
2016-11-23T11:20:28.127+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:49274 #8 (8 connections now open)
2016-11-23T11:20:28.382+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:49278 #9 (9 connections now open)
2016-11-23T11:20:28.818+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:54664 #10 (10 connections now open)
2016-11-23T11:20:28.840+0800 I ACCESS   [conn10] Unauthorized: not authorized on admin to execute command { replSetGetStatus: 1.0, forShell: 1.0 }
2016-11-23T11:20:28.964+0800 I ACCESS   [conn10] Successfully authenticated as principal ceilometer on ceilometer

Comment by lei pei [ 26/Nov/16 ]

we have three node:(172.28.9.140,172.28.9.141,172.28.9.142)

Comment by lei pei [ 26/Nov/16 ]

replica info:
{ _id: "fsp", version: 1, protocolVersion: 1, members: [ { _id: 0, host: "172.28.9.140:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 1, host: "172.28.9.141:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 2, host: "172.28.9.142:27017", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 } ], settings: { chainingAllowed: true, heartbeatIntervalMillis: 2000, heartbeatTimeoutSecs: 10, electionTimeoutMillis: 10000, getLastErrorModes: {}, getLastErrorDefaults:

{ w: 1, wtimeout: 0 }

, replicaSetId: ObjectId('5832805a9e60d600d0a351d0') } }

Comment by Kelsey Schubert [ 25/Nov/16 ]

Hi leipei2352@126.com,

Thanks for reporting this issue. Would you please attach the complete log files for each node in the replica set to this ticket, so we can continue to investigate? To resolve this issue, I would recommend performing an initial sync the affected node.

Kind regards,
Thomas

Comment by lei pei [ 25/Nov/16 ]

log @ 172.28.9.141
2016-11-23T19:42:29.287+0800 I REPL     [rsBackgroundSync] rollback diff in end of log times: -2575 seconds
2016-11-23T19:42:29.679+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:34200 #4102 (1 connection now open)
2016-11-23T19:42:29.695+0800 I ACCESS   [conn4102] Successfully authenticated as principal __system on local
2016-11-23T19:42:29.951+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:60084 #4103 (2 connections now open)
2016-11-23T19:42:29.965+0800 I ACCESS   [conn4103] Successfully authenticated as principal __system on local
2016-11-23T19:42:31.654+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:38646 #4104 (3 connections now open)
2016-11-23T19:42:31.680+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:34232 #4105 (4 connections now open)
2016-11-23T19:42:31.681+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:34234 #4106 (5 connections now open)
2016-11-23T19:42:31.681+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:34236 #4107 (6 connections now open)
2016-11-23T19:42:32.516+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:38700 #4108 (7 connections now open)
2016-11-23T19:42:32.516+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:38702 #4109 (8 connections now open)
2016-11-23T19:42:32.517+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:38704 #4110 (9 connections now open)
2016-11-23T19:42:32.522+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:38706 #4111 (10 connections now open)
2016-11-23T19:42:32.547+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:38726 #4112 (11 connections now open)
2016-11-23T19:42:32.592+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:38748 #4113 (12 connections now open)
2016-11-23T19:42:32.598+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:38756 #4114 (13 connections now open)
2016-11-23T19:42:32.601+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:38764 #4115 (14 connections now open)
2016-11-23T19:42:32.840+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:38810 #4116 (15 connections now open)
2016-11-23T19:42:32.840+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:38808 #4117 (16 connections now open)
2016-11-23T19:42:32.844+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:38816 #4118 (17 connections now open)
2016-11-23T19:42:32.894+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:38846 #4119 (18 connections now open)
2016-11-23T19:42:33.105+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:38858 #4120 (19 connections now open)
2016-11-23T19:42:33.105+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:38860 #4121 (20 connections now open)
2016-11-23T19:42:33.308+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:60166 #4122 (21 connections now open)
2016-11-23T19:42:33.308+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:60168 #4123 (22 connections now open)
2016-11-23T19:42:33.308+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:60170 #4124 (23 connections now open)
2016-11-23T19:42:33.309+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:60172 #4125 (24 connections now open)
2016-11-23T19:42:33.309+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:60174 #4126 (25 connections now open)
2016-11-23T19:42:33.309+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:60176 #4127 (26 connections now open)
2016-11-23T19:42:33.309+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:60178 #4128 (27 connections now open)
2016-11-23T19:42:33.309+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:60180 #4129 (28 connections now open)
2016-11-23T19:42:33.309+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:60182 #4130 (29 connections now open)
2016-11-23T19:42:33.309+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:60184 #4131 (30 connections now open)
2016-11-23T19:42:33.309+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:60186 #4132 (31 connections now open)
2016-11-23T19:42:33.309+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:60188 #4133 (32 connections now open)
2016-11-23T19:42:33.309+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:60190 #4134 (33 connections now open)
2016-11-23T19:42:33.310+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:60192 #4135 (34 connections now open)
2016-11-23T19:42:33.312+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:60194 #4136 (35 connections now open)
2016-11-23T19:42:33.312+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:60196 #4137 (36 connections now open)
2016-11-23T19:42:33.312+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:60198 #4138 (37 connections now open)
2016-11-23T19:42:33.312+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:60200 #4139 (38 connections now open)
2016-11-23T19:42:33.312+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:60202 #4140 (39 connections now open)
2016-11-23T19:42:33.312+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:60204 #4141 (40 connections now open)
2016-11-23T19:42:33.312+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:60206 #4142 (41 connections now open)
2016-11-23T19:42:33.313+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:60208 #4143 (42 connections now open)
2016-11-23T19:42:33.313+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:60210 #4144 (43 connections now open)
2016-11-23T19:42:33.314+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:60212 #4145 (44 connections now open)
2016-11-23T19:42:33.384+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:38908 #4146 (45 connections now open)
2016-11-23T19:42:33.451+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:38922 #4147 (46 connections now open)
2016-11-23T19:42:34.125+0800 I NETWORK  [SyncSourceFeedback] Socket say send() errno:9 Bad file descriptor 172.28.9.140:27017
2016-11-23T19:42:34.130+0800 I REPL     [SyncSourceFeedback] SyncSourceFeedback error sending update: socket exception [SEND_ERROR] for 172.28.9.140:27017
2016-11-23T19:42:34.130+0800 I REPL     [SyncSourceFeedback] updateUpstream failed: Location9001: socket exception [SEND_ERROR] for 172.28.9.140:27017, will retry
2016-11-23T19:42:35.090+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:39002 #4148 (47 connections now open)
2016-11-23T19:42:35.344+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:39032 #4149 (48 connections now open)
2016-11-23T19:42:35.417+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:39038 #4150 (49 connections now open)
2016-11-23T19:42:35.490+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:39042 #4151 (50 connections now open)
2016-11-23T19:42:35.790+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:39102 #4152 (51 connections now open)
2016-11-23T19:42:36.092+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:39131 #4153 (52 connections now open)
2016-11-23T19:42:36.346+0800 F REPL     [rsBackgroundSync] cannot rollback a collMod command: { collMod: "event", index: { expireAfterSeconds: 604800, keyPattern: { timestamp: 1 } } }
2016-11-23T19:42:36.346+0800 E REPL     [rsBackgroundSync] replica set fatal exception
2016-11-23T19:42:36.346+0800 I REPL     [rsBackgroundSync] rollback finished
2016-11-23T19:42:36.346+0800 I -        [rsBackgroundSync] Fatal assertion 28723 UnrecoverableRollbackError: need to rollback, but unable to determine common point between local and remote oplog: replica set fatal exception @ 18752
2016-11-23T19:42:36.346+0800 I -        [rsBackgroundSync]
 
***aborting after fassert() failure

Comment by lei pei [ 25/Nov/16 ]

log @ 172.28.9.141
 
2016-11-23T19:42:14.207+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.142:27017 - HostUnreachable: No route to host
2016-11-23T19:42:14.208+0800 I REPL     [ReplicationExecutor] Error in heartbeat request to 172.28.9.142:27017; HostUnreachable: No route to host
2016-11-23T19:42:14.208+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.142:27017
2016-11-23T19:42:16.722+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.140:27017
2016-11-23T19:42:17.214+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.142:27017 - HostUnreachable: No route to host
2016-11-23T19:42:17.214+0800 I REPL     [ReplicationExecutor] Error in heartbeat request to 172.28.9.142:27017; HostUnreachable: No route to host
2016-11-23T19:42:17.214+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.142:27017
2016-11-23T19:42:17.735+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.140:27017 - HostUnreachable: No route to host
2016-11-23T19:42:17.735+0800 I REPL     [ReplicationExecutor] Error in heartbeat request to 172.28.9.140:27017; HostUnreachable: No route to host
2016-11-23T19:42:17.735+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.140:27017
2016-11-23T19:42:20.220+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.142:27017 - HostUnreachable: No route to host
2016-11-23T19:42:20.220+0800 I REPL     [ReplicationExecutor] Error in heartbeat request to 172.28.9.142:27017; HostUnreachable: No route to host
2016-11-23T19:42:20.740+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.140:27017 - HostUnreachable: No route to host
2016-11-23T19:42:20.740+0800 I REPL     [ReplicationExecutor] Error in heartbeat request to 172.28.9.140:27017; HostUnreachable: No route to host
2016-11-23T19:42:20.740+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.140:27017
2016-11-23T19:42:21.127+0800 I REPL     [ReplicationExecutor] Not starting an election, since we are not electable
2016-11-23T19:42:23.746+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.140:27017 - HostUnreachable: No route to host
2016-11-23T19:42:23.746+0800 I REPL     [ReplicationExecutor] Error in heartbeat request to 172.28.9.140:27017; HostUnreachable: No route to host
2016-11-23T19:42:25.220+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.142:27017
2016-11-23T19:42:26.232+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.142:27017 - HostUnreachable: No route to host
2016-11-23T19:42:26.233+0800 I REPL     [ReplicationExecutor] Error in heartbeat request to 172.28.9.142:27017; HostUnreachable: No route to host
2016-11-23T19:42:26.233+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.142:27017
2016-11-23T19:42:27.254+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Successfully connected to 172.28.9.142:27017
2016-11-23T19:42:27.254+0800 I REPL     [ReplicationExecutor] Member 172.28.9.142:27017 is now in state SECONDARY
2016-11-23T19:42:27.312+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:58966 #4097 (20 connections now open)
2016-11-23T19:42:27.312+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:58960 #4098 (21 connections now open)
2016-11-23T19:42:27.327+0800 I ACCESS   [conn4098] Successfully authenticated as principal __system on local
2016-11-23T19:42:28.185+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:33204 #4099 (22 connections now open)
2016-11-23T19:42:28.745+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.3:33658 #4100 (23 connections now open)
2016-11-23T19:42:28.746+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.140:27017
2016-11-23T19:42:28.764+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Successfully connected to 172.28.9.140:27017
2016-11-23T19:42:28.764+0800 I REPL     [ReplicationExecutor] Member 172.28.9.140:27017 is now in state PRIMARY
2016-11-23T19:42:28.780+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:59898 #4101 (24 connections now open)
2016-11-23T19:42:29.089+0800 I REPL     [ReplicationExecutor] syncing from: 172.28.9.140:27017
2016-11-23T19:42:29.105+0800 I REPL     [SyncSourceFeedback] setting syncSourceFeedback to 172.28.9.140:27017
2016-11-23T19:42:29.105+0800 I ASIO     [NetworkInterfaceASIO-BGSync-0] Connecting to 172.28.9.140:27017
2016-11-23T19:42:29.124+0800 I ASIO     [NetworkInterfaceASIO-BGSync-0] Successfully connected to 172.28.9.140:27017
2016-11-23T19:42:29.197+0800 I REPL     [rsBackgroundSync] Starting rollback due to OplogStartMissing: our last op time fetched: (term: 8, timestamp: Nov 23 18:59:29:1e). source's GTE: (term: 9, timestamp: Nov 23 19:42:22:2) hashes: (-3277267292035300703/7785406698297562941)
2016-11-23T19:42:29.232+0800 I REPL     [rsBackgroundSync] beginning rollback
2016-11-23T19:42:29.232+0800 I REPL     [rsBackgroundSync] rollback 0
2016-11-23T19:42:29.232+0800 I REPL     [ReplicationExecutor] transition to ROLLBACK
2016-11-23T19:42:29.232+0800 I NETWORK  [conn4100] end connection 172.28.0.3:33658 (23 connections now open)
2016-11-23T19:42:29.232+0800 I NETWORK  [conn4101] end connection 172.28.0.2:59898 (23 connections now open)
2016-11-23T19:42:29.232+0800 I NETWORK  [conn4087] end connection 172.28.0.4:43702 (23 connections now open)
2016-11-23T19:42:29.233+0800 I NETWORK  [conn4089] end connection 172.28.0.4:43714 (23 connections now open)
2016-11-23T19:42:29.233+0800 I NETWORK  [conn4057] end connection 172.28.0.4:54304 (23 connections now open)
2016-11-23T19:42:29.233+0800 I NETWORK  [conn4059] end connection 172.28.0.4:54310 (23 connections now open)
2016-11-23T19:42:29.233+0800 I NETWORK  [conn4060] end connection 172.28.0.4:54314 (23 connections now open)
2016-11-23T19:42:29.233+0800 I NETWORK  [conn4092] end connection 172.28.0.4:43742 (21 connections now open)
2016-11-23T19:42:29.233+0800 I NETWORK  [conn4088] end connection 172.28.0.4:43708 (20 connections now open)
2016-11-23T19:42:29.233+0800 I NETWORK  [conn4056] end connection 172.28.0.4:54272 (20 connections now open)
2016-11-23T19:42:29.233+0800 I NETWORK  [conn4062] end connection 172.28.0.4:54324 (18 connections now open)
2016-11-23T19:42:29.233+0800 I NETWORK  [conn4090] end connection 172.28.0.4:43720 (16 connections now open)
2016-11-23T19:42:29.233+0800 I NETWORK  [conn4044] end connection 172.28.0.4:54160 (13 connections now open)
2016-11-23T19:42:29.233+0800 I NETWORK  [conn4093] end connection 172.28.0.4:43752 (10 connections now open)
2016-11-23T19:42:29.234+0800 I NETWORK  [conn4094] end connection 172.28.0.4:43758 (9 connections now open)
2016-11-23T19:42:29.234+0800 I NETWORK  [conn4091] end connection 172.28.0.4:43734 (8 connections now open)
2016-11-23T19:42:29.234+0800 I NETWORK  [conn4061] end connection 172.28.0.4:54318 (7 connections now open)
2016-11-23T19:42:29.234+0800 I NETWORK  [conn4058] end connection 172.28.0.4:54306 (6 connections now open)
2016-11-23T19:42:29.235+0800 I NETWORK  [conn4063] end connection 172.28.0.4:54344 (5 connections now open)
2016-11-23T19:42:29.235+0800 I NETWORK  [conn4045] end connection 172.28.0.4:54162 (4 connections now open)
2016-11-23T19:42:29.235+0800 I NETWORK  [conn4037] end connection 172.28.0.4:54146 (3 connections now open)
2016-11-23T19:42:29.235+0800 I NETWORK  [conn4097] end connection 172.28.0.2:58966 (2 connections now open)
2016-11-23T19:42:29.235+0800 I NETWORK  [conn4098] end connection 172.28.0.2:58960 (1 connection now open)
2016-11-23T19:42:29.235+0800 I REPL     [rsBackgroundSync] rollback 1
2016-11-23T19:42:29.235+0800 I NETWORK  [conn4099] end connection 172.28.0.3:33204 (0 connections now open)
2016-11-23T19:42:29.278+0800 I REPL     [rsBackgroundSync] rollback 2 FindCommonPoint
2016-11-23T19:42:29.287+0800 I REPL     [rsBackgroundSync] rollback our last optime:   Nov 23 18:59:29:1e
2016-11-23T19:42:29.287+0800 I REPL     [rsBackgroundSync] rollback their last optime: Nov 23 19:42:24:2c
2016-11-23T19:42:29.287+0800 I REPL     [rsBackgroundSync] rollback diff in end of log times: -2575 seconds

Comment by lei pei [ 25/Nov/16 ]

log @ 172.28.9.141
 
2016-11-22T19:11:55.209+0800 I REPL     [ReplicationExecutor] Error in heartbeat request to 172.28.9.140:27017; ExceededTimeLimit: Operation timed out
2016-11-22T19:11:55.209+0800 I REPL     [ReplicationExecutor] Error in heartbeat request to 172.28.9.142:27017; ExceededTimeLimit: Operation timed out
2016-11-22T19:11:55.215+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36132 #550 (5 connections now open)
2016-11-22T19:11:55.238+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36134 #551 (6 connections now open)
2016-11-22T19:11:55.252+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36136 #552 (7 connections now open)
2016-11-22T19:11:55.596+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36140 #553 (8 connections now open)
2016-11-22T19:11:55.641+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36142 #554 (9 connections now open)
2016-11-22T19:11:55.651+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36144 #555 (10 connections now open)
2016-11-22T19:11:55.651+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36146 #556 (11 connections now open)
2016-11-22T19:11:55.678+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36148 #557 (12 connections now open)
2016-11-22T19:11:55.687+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36150 #558 (13 connections now open)
2016-11-22T19:11:55.760+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36154 #559 (14 connections now open)
2016-11-22T19:11:55.761+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36156 #560 (15 connections now open)
2016-11-22T19:11:56.117+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36158 #561 (16 connections now open)
2016-11-22T19:11:56.718+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36162 #562 (17 connections now open)
2016-11-22T19:11:57.213+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36164 #563 (18 connections now open)
2016-11-22T19:11:57.537+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36168 #564 (19 connections now open)
2016-11-22T19:11:57.537+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36170 #565 (20 connections now open)
2016-11-22T19:11:57.715+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36172 #566 (21 connections now open)
2016-11-22T19:11:58.771+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36174 #567 (22 connections now open)
2016-11-22T19:11:58.771+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36176 #568 (23 connections now open)
2016-11-22T19:12:00.209+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.140:27017
2016-11-22T19:12:00.209+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.142:27017
2016-11-22T19:12:01.985+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36186 #569 (24 connections now open)
2016-11-22T19:12:03.156+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36190 #570 (25 connections now open)
2016-11-22T19:12:03.263+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.4:36194 #571 (26 connections now open)
2016-11-22T19:12:04.306+0800 I REPL     [ReplicationExecutor] Not starting an election, since we are not electable
2016-11-22T19:12:10.209+0800 I REPL     [ReplicationExecutor] Error in heartbeat request to 172.28.9.140:27017; ExceededTimeLimit: Couldn't get a connection within the time limit
2016-11-22T19:12:10.209+0800 I REPL     [ReplicationExecutor] Error in heartbeat request to 172.28.9.142:27017; ExceededTimeLimit: Couldn't get a connection within the time limit
2016-11-22T19:12:14.409+0800 I REPL     [ReplicationExecutor] Not starting an election, since we are not electable
2016-11-22T19:12:20.209+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.140:27017 - ExceededTimeLimit: Operation timed out
2016-11-22T19:12:20.209+0800 I REPL     [ReplicationExecutor] Error in heartbeat request to 172.28.9.140:27017; ExceededTimeLimit: Operation timed out
2016-11-22T19:12:20.210+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.140:27017
2016-11-22T19:12:20.210+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Failed to connect to 172.28.9.142:27017 - ExceededTimeLimit: Operation timed out
2016-11-22T19:12:20.210+0800 I REPL     [ReplicationExecutor] Error in heartbeat request to 172.28.9.142:27017; ExceededTimeLimit: Operation timed out
2016-11-22T19:12:20.210+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Connecting to 172.28.9.142:27017
2016-11-22T19:23:33.958+0800 I CONTROL  [main] ***** SERVER RESTARTED *****
2016-11-22T19:23:34.062+0800 I CONTROL  [initandlisten] MongoDB starting : pid=18828 port=27017 dbpath=/var/ceilometer 64-bit host=28BAD738-1DD2-11B2-9C46-0018E1C5D866
2016-11-22T19:23:34.062+0800 I CONTROL  [initandlisten] db version v3.2.10
2016-11-22T19:23:34.062+0800 I CONTROL  [initandlisten] git version: ed70e33130c977bda0024c125b56d159573dbaf0
2016-11-22T19:23:34.062+0800 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.0.1e-fips 11 Feb 2013
2016-11-22T19:23:34.062+0800 I CONTROL  [initandlisten] allocator: tcmalloc
2016-11-22T19:23:34.062+0800 I CONTROL  [initandlisten] modules: none
2016-11-22T19:23:34.062+0800 I CONTROL  [initandlisten] build environment:
2016-11-22T19:23:34.062+0800 I CONTROL  [initandlisten]     distarch: x86_64
2016-11-22T19:23:34.062+0800 I CONTROL  [initandlisten]     target_arch: x86_64
2016-11-22T19:23:34.062+0800 I CONTROL  [initandlisten] options: { config: "/etc/mongodb/mongodb.conf", net: { bindIp: "172.28.9.141" }, processManagement: { fork: true }, replication: { oplogSizeMB: 3072, replSet: "fsp" }, security: { authorization: "enabled", keyFile: "/etc/mongodb/mongodb-keyfile" }, storage: { dbPath: "/var/ceilometer", mmapv1: { smallFiles: true } }, systemLog: { destination: "file", logAppend: true, path: "/var/log/fusionsphere/component/mongodb/mongodb.log" } }
2016-11-22T19:23:34.090+0800 I -        [initandlisten] Detected data files in /var/ceilometer created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2016-11-22T19:23:34.090+0800 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=36G,session_max=20000,eviction=(threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0),
2016-11-22T19:23:38.673+0800 I STORAGE  [initandlisten] Starting WiredTigerRecordStoreThread local.oplog.rs
2016-11-22T19:23:38.673+0800 I STORAGE  [initandlisten] The size storer reports that the oplog contains 253799 records totaling to 168909415 bytes
2016-11-22T19:23:38.745+0800 I STORAGE  [initandlisten] Sampling from the oplog between Nov 21 13:04:26:1 and Nov 22 19:11:38:a to determine where to place markers for truncation
2016-11-22T19:23:38.745+0800 I STORAGE  [initandlisten] Taking 52 samples and assuming that each section of oplog contains approximately 48402 records totaling to 32212709 bytes
2016-11-22T19:23:40.611+0800 I STORAGE  [initandlisten] Placing a marker at optime Nov 22 01:06:41:37
2016-11-22T19:23:40.612+0800 I STORAGE  [initandlisten] Placing a marker at optime Nov 22 08:17:24:27
2016-11-22T19:23:40.612+0800 I STORAGE  [initandlisten] Placing a marker at optime Nov 22 12:41:00:2b
2016-11-22T19:23:40.612+0800 I STORAGE  [initandlisten] Placing a marker at optime Nov 22 15:12:23:19
2016-11-22T19:23:40.612+0800 I STORAGE  [initandlisten] Placing a marker at optime Nov 22 18:25:31:2
2016-11-22T19:23:40.710+0800 W STORAGE  [initandlisten] Detected configuration for non-active storage engine mmapv1 when current storage engine is wiredTiger
2016-11-22T19:23:40.710+0800 I CONTROL  [initandlisten]
2016-11-22T19:23:40.710+0800 I CONTROL  [initandlisten] ** WARNING: /sys/kernel/mm/transparent_hugepage/enabled is 'always'.
2016-11-22T19:23:40.710+0800 I CONTROL  [initandlisten] **        We suggest setting it to 'never'
2016-11-22T19:23:40.710+0800 I CONTROL  [initandlisten]
2016-11-22T19:23:40.710+0800 I CONTROL  [initandlisten] ** WARNING: soft rlimits too low. The locked memory size is 32768 bytes, it should be at least 65536 bytes
2016-11-22T19:23:40.710+0800 I CONTROL  [initandlisten]
2016-11-22T19:23:40.710+0800 I CONTROL  [initandlisten] ** WARNING: soft rlimits too low. rlimits set to 16384 processes, 65536 files. Number of processes should be at least 32768 : 0.5 times number of files.
2016-11-22T19:23:40.710+0800 I CONTROL  [initandlisten]
2016-11-22T19:23:40.828+0800 I FTDC     [initandlisten] Initializing full-time diagnostic data capture with directory '/var/ceilometer/diagnostic.data'
2016-11-22T19:23:40.828+0800 I NETWORK  [HostnameCanonicalizationWorker] Starting hostname canonicalization worker
2016-11-22T19:23:40.832+0800 I NETWORK  [initandlisten] waiting for connections on port 27017
2016-11-22T19:23:40.836+0800 I NETWORK  [initandlisten] connection accepted from 172.28.0.2:43506 #1 (1 connection now open)

Comment by lei pei [ 25/Nov/16 ]

Sorry,correctly speak, the node rollback failed has two unclean shutdown for the host was forced restart.

Generated at Thu Feb 08 04:14:24 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.