[SERVER-22392] "Operation timed out" when enableSharding on new cluster - MongoDB

Details

Type: Bug
Status: Closed
Priority: Major - P3
Resolution: Gone away
Affects Version/s: 3.2.1
Fix Version/s: None
Component/s: Sharding
Labels:
None

Operating System:
ALL
Steps To Reproduce:

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")`
Sprint:
Sharding 10 (02/19/16), Sharding 11 (03/11/16)
Linked BF Score:
0

Description

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.

Attachments

Options
- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

Attachments

mongod-config-server-logs.tar.gz
220 kB
Feb 01 2016 11:30:11 AM UTC

Issue Links

is related to

SERVER-22427 Add additional diagnostics to "Operation timed out" errors returned from NetworkInterfaceASIO

Closed

SERVER-22428 Log read-after-optime timeouts

Closed

"Operation timed out" when enableSharding on new cluster

Details

Description

Attachments

Attachments

Issue Links

Activity

People

Dates