[SERVER-72427] Stuck creating index with "Index Build: draining writes received during build" Created: 29/Dec/22  Updated: 02/Jan/23  Resolved: 02/Jan/23

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

Type: Bug Priority: Major - P3
Reporter: Snir David Assignee: Chris Kelly
Resolution: Done Votes: 0
Labels: cluster, index, indexes, indexing
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Operating System: ALL
Participants:

 Description   

I have checked out the previous issues: https://jira.mongodb.org/browse/SERVER-50665 and https://jira.mongodb.org/browse/SERVER-48516

I have ensured a keyfile exists, and I then stopped and started the servers again (in the recommended order, first stop secondaries then master, etc.)

None of this helped and I have no idea what to do.

Mongo version 5.0.14

 

The `op` output for example:

```
{
  type: 'op',
  host: 'mongo02:27017',
  desc: 'IndexBuildsCoordinatorMongod-2',
  active: false,
  currentOpTime: '2022-12-29T16:15:18.739+00:00',
  opid: 7,
  secs_running: Long("840"),
  microsecs_running: Long("840383035"),
  op: 'command',
  ns: 'captainup.actions',
  command: {
    createIndexes: 'actions',
    indexes: [
     

{         v: 2,         key: [Object],         name: 'store_id_1_name_1_timestamp_1',         sparse: false       }

    ]
  },
  msg: 'Index Build: draining writes received during build',
  numYields: 3114,
  locks: {},
  waitingForLock: false,
  lockStats: {
    FeatureCompatibilityVersion: { acquireCount:

{ w: Long("4136") }

},
    ReplicationStateTransition:

{       acquireCount: \{ w: Long("4137") }

,
      acquireWaitCount: { w: Long("1") },
      timeAcquiringMicros: { w: Long("779") }
    },
    Global:

{       acquireCount: \{ w: Long("4136") }

,
      acquireWaitCount: { w: Long("5") },
      timeAcquiringMicros: { w: Long("14438") }
    },
    Database: { acquireCount:

{ w: Long("4136") }

},
    Collection: { acquireCount:

{ w: Long("4135"), R: Long("1") }

}
  },
  waitingForFlowControl: false,
  flowControlStats: { acquireCount: Long("3944"), timeAcquiringMicros: Long("2025") }
}
```
 
A few lines relevant from the `mongod.log`:
```

{"t":\{"$date":"2022-12-29T16:17:12.123+00:00"}

,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-1","msg":"Index build: drained side writes","attr":{"index":"store_id_1_name_1_timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":534,"totalInserted":534,"totalDeleted":0,"durationMillis":2}}

{"t":\{"$date":"2022-12-29T16:17:12.706+00:00"}

,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build: drained side writes","attr":{"index":"timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":529,"totalInserted":529,"totalDeleted":0,"durationMillis":24}}

{"t":\{"$date":"2022-12-29T16:17:13.127+00:00"}

,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-1","msg":"Index build: drained side writes","attr":{"index":"store_id_1_name_1_timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":547,"totalInserted":547,"totalDeleted":0,"durationMillis":2}}

{"t":\{"$date":"2022-12-29T16:17:13.709+00:00"}

,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build: drained side writes","attr":{"index":"timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":534,"totalInserted":534,"totalDeleted":0,"durationMillis":2}}

{"t":\{"$date":"2022-12-29T16:17:14.131+00:00"}

,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-1","msg":"Index build: drained side writes","attr":{"index":"store_id_1_name_1_timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":511,"totalInserted":511,"totalDeleted":0,"durationMillis":2}}

{"t":\{"$date":"2022-12-29T16:17:14.712+00:00"}

,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build: drained side writes","attr":{"index":"timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":523,"totalInserted":523,"totalDeleted":0,"durationMillis":1}}

{"t":\{"$date":"2022-12-29T16:17:15.135+00:00"}

,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-1","msg":"Index build: drained side writes","attr":{"index":"store_id_1_name_1_timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":528,"totalInserted":528,"totalDeleted":0,"durationMillis":2}}

{"t":\{"$date":"2022-12-29T16:17:15.715+00:00"}

,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build: drained side writes","attr":{"index":"timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":498,"totalInserted":498,"totalDeleted":0,"durationMillis":2}}

{"t":\{"$date":"2022-12-29T16:17:16.138+00:00"}

,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-1","msg":"Index build: drained side writes","attr":{"index":"store_id_1_name_1_timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":515,"totalInserted":515,"totalDeleted":0,"durationMillis":2}}

{"t":\{"$date":"2022-12-29T16:17:16.717+00:00"}

,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build: drained side writes","attr":{"index":"timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":519,"totalInserted":519,"totalDeleted":0,"durationMillis":1}}

{"t":\{"$date":"2022-12-29T16:17:17.142+00:00"}

,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-1","msg":"Index build: drained side writes","attr":{"index":"store_id_1_name_1_timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":517,"totalInserted":517,"totalDeleted":0,"durationMillis":2}}

{"t":\{"$date":"2022-12-29T16:17:17.720+00:00"}

,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build: drained side writes","attr":{"index":"timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":536,"totalInserted":536,"totalDeleted":0,"durationMillis":1}}

{"t":\{"$date":"2022-12-29T16:17:18.145+00:00"}

,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-1","msg":"Index build: drained side writes","attr":{"index":"store_id_1_name_1_timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":527,"totalInserted":527,"totalDeleted":0,"durationMillis":2}}

{"t":\{"$date":"2022-12-29T16:17:18.722+00:00"}

,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build: drained side writes","attr":{"index":"timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":471,"totalInserted":471,"totalDeleted":0,"durationMillis":1}}

{"t":\{"$date":"2022-12-29T16:17:19.148+00:00"}

,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-1","msg":"Index build: drained side writes","attr":{"index":"store_id_1_name_1_timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":413,"totalInserted":413,"totalDeleted":0,"durationMillis":1}}

{"t":\{"$date":"2022-12-29T16:17:19.725+00:00"}

,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build: drained side writes","attr":{"index":"timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":433,"totalInserted":433,"totalDeleted":0,"durationMillis":1}}

{"t":\{"$date":"2022-12-29T16:17:20.152+00:00"}

,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-1","msg":"Index build: drained side writes","attr":{"index":"store_id_1_name_1_timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":542,"totalInserted":542,"totalDeleted":0,"durationMillis":2}}

{"t":\{"$date":"2022-12-29T16:17:20.727+00:00"}

,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build: drained side writes","attr":{"index":"timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":533,"totalInserted":533,"totalDeleted":0,"durationMillis":1}}

{"t":\{"$date":"2022-12-29T16:17:21.155+00:00"}

,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-1","msg":"Index build: drained side writes","attr":{"index":"store_id_1_name_1_timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":486,"totalInserted":486,"totalDeleted":0,"durationMillis":2}}

{"t":\{"$date":"2022-12-29T16:17:21.729+00:00"}

,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-0","msg":"Index build: drained side writes","attr":{"index":"timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":500,"totalInserted":500,"totalDeleted":0,"durationMillis":1}}

{"t":\{"$date":"2022-12-29T16:17:22.158+00:00"}

,"s":"I",  "c":"INDEX",    "id":20689,   "ctx":"IndexBuildsCoordinatorMongod-1","msg":"Index build: drained side writes","attr":{"index":"store_id_1_name_1_timestamp_1","collectionUUID":{"uuid":{"$uuid":"8e1e6c02-1f20-4645-a3b2-1e1fb32ea7f5"}},"namespace":"captainup.actions","numApplied":492,"totalInserted":492,"totalDeleted":0,"durationMillis":2}}
```
 
Important to say: indexes did work before in my setup. Nothing changed, I just tried to create a few new indices and that happened.



 Comments   
Comment by Chris Kelly [ 02/Jan/23 ]

Thanks for dropping a comment to let us know it's resolved! I'll go ahead and close the ticket.

Comment by Snir David [ 29/Dec/22 ]

Resolved.

One node was at "RECOVERY" mode - a hard reset (by force deleting all the internal wt files) got it out of this recovery loop.

Generated at Thu Feb 08 06:21:46 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.