Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-22392

"Operation timed out" when enableSharding on new cluster

    • Type: Icon: Bug Bug
    • Resolution: Done
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: 3.2.1
    • Component/s: Sharding
    • None
    • ALL
    • Hide

      1. Create 6 replication sets with 3 nodes each
      2. Set clusterRole to configsvr on one shard to make it config RS
      3. Set clusterRole on others to shardsvr
      3. Run rs.initiate() on 'first' node of each shard
      4. Run db.CreateUser to create admin user (role: "root") on 'first' node of each shard
      5. Run mongos pointing to config servers
      6. Connect to mongos, add shards
      7. Try to enable sharding `sh.enableSharding("my-db")`

      Show
      1. Create 6 replication sets with 3 nodes each 2. Set clusterRole to configsvr on one shard to make it config RS 3. Set clusterRole on others to shardsvr 3. Run rs.initiate() on 'first' node of each shard 4. Run db.CreateUser to create admin user (role: "root") on 'first' node of each shard 5. Run mongos pointing to config servers 6. Connect to mongos, add shards 7. Try to enable sharding `sh.enableSharding("my-db")`
    • Sharding 10 (02/19/16), Sharding 11 (03/11/16)
    • 0

      Given a mongodb 3.2.1 cluster with multiple shards, enabling sharding for a database yields "Operation timed out":

      mongos>   sh.enableSharding("my-db")
      { "ok" : 0, "errmsg" : "Operation timed out", "code" : 50 }
      

      Adding shards worked just fine but sh.status() also shows timeout issues:

      mongos> sh.status(true)
      --- Sharding Status --- 
        sharding version: {
      	"_id" : 1,
      	"minCompatibleVersion" : 5,
      	"currentVersion" : 6,
      	"clusterId" : ObjectId("56af2c8c9a517ed41619c719")
      }
        shards:
      	{  "_id" : "replA",  "host" : "replA/replA-0.mongodb-shardsvr.service.q:27017,replA-1.mongodb-shardsvr.service.q:27017,replA-2.mongodb-shardsvr.service.q:27017" }
      	{  "_id" : "replB",  "host" : "replB/replB-0.mongodb-shardsvr.service.q:27017,replB-1.mongodb-shardsvr.service.q:27017,replB-2.mongodb-shardsvr.service.q:27017" }
      	{  "_id" : "replC",  "host" : "replC/replC-0.mongodb-shardsvr.service.q:27017,replC-1.mongodb-shardsvr.service.q:27017,replC-2.mongodb-shardsvr.service.q:27017" }
      	{  "_id" : "replD",  "host" : "replD/replD-0.mongodb-shardsvr.service.q:27017,replD-1.mongodb-shardsvr.service.q:27017,replD-2.mongodb-shardsvr.service.q:27017" }
      	{  "_id" : "replE",  "host" : "replE/replE-0.mongodb-shardsvr.service.q:27017,replE-1.mongodb-shardsvr.service.q:27017,replE-2.mongodb-shardsvr.service.q:27017" }
        active mongoses:
      	{  "_id" : "ip-10-1-45-192:27018",  "ping" : ISODate("2016-02-01T11:12:25.013Z"),  "up" : NumberLong(4363),  "waiting" : false,  "mongoVersion" : "3.2.1" }
      	{  "_id" : "ip-10-1-45-220:27018",  "ping" : ISODate("2016-02-01T11:12:24.552Z"),  "up" : NumberLong(4363),  "waiting" : false,  "mongoVersion" : "3.2.1" }
      	{  "_id" : "ip-10-1-47-28:27018",  "ping" : ISODate("2016-02-01T11:12:24.434Z"),  "up" : NumberLong(4362),  "waiting" : false,  "mongoVersion" : "3.2.1" }
      	{  "_id" : "ip-10-1-40-26:27018",  "ping" : ISODate("2016-02-01T11:12:24.251Z"),  "up" : NumberLong(4363),  "waiting" : false,  "mongoVersion" : "3.2.1" }
      	{  "_id" : "ip-10-1-24-168:27018",  "ping" : ISODate("2016-02-01T11:12:24.050Z"),  "up" : NumberLong(4362),  "waiting" : false,  "mongoVersion" : "3.2.1" }
      	{  "_id" : "ip-10-1-29-10:27017",  "ping" : ISODate("2016-02-01T11:12:24.047Z"),  "up" : NumberLong(4362),  "waiting" : false,  "mongoVersion" : "3.2.1" }
      	{  "_id" : "ip-10-1-24-208:27018",  "ping" : ISODate("2016-02-01T11:12:24.044Z"),  "up" : NumberLong(4362),  "waiting" : false,  "mongoVersion" : "3.2.1" }
      	{  "_id" : "ip-10-1-11-238:27017",  "ping" : ISODate("2016-02-01T11:12:23.750Z"),  "up" : NumberLong(4361),  "waiting" : false,  "mongoVersion" : "3.2.1" }
      	{  "_id" : "ip-10-1-46-222:27018",  "ping" : ISODate("2016-02-01T11:12:23.686Z"),  "up" : NumberLong(4362),  "waiting" : false,  "mongoVersion" : "3.2.1" }
      	{  "_id" : "ip-10-1-27-15:27018",  "ping" : ISODate("2016-02-01T11:12:23.559Z"),  "up" : NumberLong(4361),  "waiting" : false,  "mongoVersion" : "3.2.1" }
      	{  "_id" : "ip-10-1-45-146:27018",  "ping" : ISODate("2016-02-01T11:12:23.529Z"),  "up" : NumberLong(4362),  "waiting" : false,  "mongoVersion" : "3.2.1" }
      	{  "_id" : "ip-10-1-26-190:27018",  "ping" : ISODate("2016-02-01T11:12:23.325Z"),  "up" : NumberLong(4361),  "waiting" : false,  "mongoVersion" : "3.2.1" }
      	{  "_id" : "ip-10-1-28-139:27018",  "ping" : ISODate("2016-02-01T11:12:23.253Z"),  "up" : NumberLong(4362),  "waiting" : false,  "mongoVersion" : "3.2.1" }
      	{  "_id" : "ip-10-1-8-127:27018",  "ping" : ISODate("2016-02-01T11:12:23.206Z"),  "up" : NumberLong(4362),  "waiting" : false,  "mongoVersion" : "3.2.1" }
      	{  "_id" : "ip-10-1-25-107:27018",  "ping" : ISODate("2016-02-01T11:12:23.206Z"),  "up" : NumberLong(4362),  "waiting" : false,  "mongoVersion" : "3.2.1" }
      	{  "_id" : "ip-10-1-8-239:27018",  "ping" : ISODate("2016-02-01T11:12:22.988Z"),  "up" : NumberLong(4360),  "waiting" : false,  "mongoVersion" : "3.2.1" }
      	{  "_id" : "ip-10-1-11-26:27018",  "ping" : ISODate("2016-02-01T11:12:22.986Z"),  "up" : NumberLong(4361),  "waiting" : false,  "mongoVersion" : "3.2.1" }
      	{  "_id" : "ip-10-1-10-142:27018",  "ping" : ISODate("2016-02-01T11:12:22.970Z"),  "up" : NumberLong(4361),  "waiting" : false,  "mongoVersion" : "3.2.1" }
      	{  "_id" : "ip-10-1-10-41:27018",  "ping" : ISODate("2016-02-01T11:12:22.131Z"),  "up" : NumberLong(4360),  "waiting" : false,  "mongoVersion" : "3.2.1" }
      	{  "_id" : "ip-10-1-11-229:27018",  "ping" : ISODate("2016-02-01T11:12:16.815Z"),  "up" : NumberLong(3640),  "waiting" : false,  "mongoVersion" : "3.2.1" }
        balancer:
      	Currently enabled:  yes
      	Currently running:  no
      	Failed balancer rounds in last 5 attempts:  5
      	Last reported error:  could not get updated shard list from config server due to ExceededTimeLimit Operation timed out
      	Time of Reported error:  Mon Feb 01 2016 11:12:14 GMT+0000 (UTC)
      	Migration Results for the last 24 hours: 
      		No recent migrations
        databases:
      

      On the config server RS, rs.status() looks good:

      configReplSet:PRIMARY> rs.status()
      {
      	"set" : "configReplSet",
      	"date" : ISODate("2016-02-01T11:15:52.962Z"),
      	"myState" : 1,
      	"term" : NumberLong(1),
      	"configsvr" : true,
      	"heartbeatIntervalMillis" : NumberLong(2000),
      	"members" : [
      		{
      			"_id" : 0,
      			"name" : "configReplSet-0.mongodb-configsvr.service.q:27017",
      			"health" : 1,
      			"state" : 1,
      			"stateStr" : "PRIMARY",
      			"uptime" : 4588,
      			"optime" : {
      				"ts" : Timestamp(1454325351, 1),
      				"t" : NumberLong(1)
      			},
      			"optimeDate" : ISODate("2016-02-01T11:15:51Z"),
      			"electionTime" : Timestamp(1454320777, 1),
      			"electionDate" : ISODate("2016-02-01T09:59:37Z"),
      			"configVersion" : 1,
      			"self" : true
      		},
      		{
      			"_id" : 1,
      			"name" : "configReplSet-1.mongodb-configsvr.service.q:27017",
      			"health" : 1,
      			"state" : 2,
      			"stateStr" : "SECONDARY",
      			"uptime" : 4586,
      			"optime" : {
      				"ts" : Timestamp(1454325348, 1),
      				"t" : NumberLong(1)
      			},
      			"optimeDate" : ISODate("2016-02-01T11:15:48Z"),
      			"lastHeartbeat" : ISODate("2016-02-01T11:15:51.718Z"),
      			"lastHeartbeatRecv" : ISODate("2016-02-01T11:15:51.271Z"),
      			"pingMs" : NumberLong(0),
      			"syncingTo" : "configReplSet-0.mongodb-configsvr.service.q:27017",
      			"configVersion" : 1
      		},
      		{
      			"_id" : 2,
      			"name" : "configReplSet-2.mongodb-configsvr.service.q:27017",
      			"health" : 1,
      			"state" : 2,
      			"stateStr" : "SECONDARY",
      			"uptime" : 4586,
      			"optime" : {
      				"ts" : Timestamp(1454325351, 1),
      				"t" : NumberLong(1)
      			},
      			"optimeDate" : ISODate("2016-02-01T11:15:51Z"),
      			"lastHeartbeat" : ISODate("2016-02-01T11:15:51.883Z"),
      			"lastHeartbeatRecv" : ISODate("2016-02-01T11:15:51.774Z"),
      			"pingMs" : NumberLong(0),
      			"syncingTo" : "configReplSet-0.mongodb-configsvr.service.q:27017",
      			"configVersion" : 1
      		}
      	],
      	"ok" : 1
      }
      

      All this was working when I did the same on 3.2.0 without authentication. So it's either related to the authentication or a regression in 3.2.1. I'll try to reproduce this with 3.2.1 now.

            Assignee:
            spencer@mongodb.com Spencer Brody (Inactive)
            Reporter:
            fish Johannes Ziemke
            Votes:
            0 Vote for this issue
            Watchers:
            10 Start watching this issue

              Created:
              Updated:
              Resolved: