[SERVER-46668] createIndexes command does not honor wtimeout when replication is disabled on v4.5.0-24-gb801dec Created: 06/Mar/20  Updated: 27/Oct/23  Resolved: 02/Apr/20

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

Type: Bug Priority: Major - P3
Reporter: Shane Harvey Assignee: Benety Goh
Resolution: Works as Designed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Zip Archive server-logs-PYTHON-2153.zip    
Issue Links:
Problem/Incident
causes PYTHON-2153 test_raise_wtimeout hangs on 4.5 latest Closed
Related
is related to SERVER-34776 dropDatabase should respect user prov... Closed
is related to SERVER-45201 Implicit collection creation from cre... Closed
is related to SERVER-45001 enable commit quorum for two phase in... Closed
Operating System: ALL
Sprint: Execution Team 2020-04-06
Participants:

 Description   

The python driver has a test to ensure that write commands properly raise an error when wtimeout is exceeded. The test runs on a replica set and disables replication on all secondaries using the stopReplProducer fail point.

The test hangs when running a createIndexes command with "writeConcern":{"wtimeout":1,"w":3} on the following server version:

 [2020/03/05 10:36:29.083] db version v4.5.0-24-gb801dec
 [2020/03/05 10:36:29.083] git version: b801dec04f01dfa374a5d73e187ac793ae079dc5
 [2020/03/05 10:36:29.083] OpenSSL version: OpenSSL 1.0.2g  1 Mar 2016
 [2020/03/05 10:36:29.083] allocator: tcmalloc
 [2020/03/05 10:36:29.083] modules: enterprise
 [2020/03/05 10:36:29.083] build environment:
 [2020/03/05 10:36:29.085]     distmod: ubuntu1604
 [2020/03/05 10:36:29.085]     distarch: x86_64
 [2020/03/05 10:36:29.085]     target_arch: x86_64

The createIndexes occurs on conn509:

 {"t":{"$date":"2020-03-05T18:40:26.258+0000"},"s":"I", "c":"INDEX",   "id":20438,"ctx":"conn509","msg":"Registering index build: {buildUUID}","attr":           {"buildUUID":{"uuid":{"$uuid":"92da4727-7623-46f4-ac2e-1856a5edba91"}}}}
 {"t":{"$date":"2020-03-05T18:40:26.258+0000"},"s":"D1","c":"STORAGE", "id":51780,"ctx":"IndexBuildsCoordinatorMongod-1","msg":"create uri: {uri} config:        {config}","attr":{"uri":"table:index-3206-8434647472929354996","config":"type=file,internal_page_max=16k,leaf_page_max=16k,checksum=on,prefix_compression=true, block_compressor=,,,,key_format=u,value_format=u,app_metadata=(formatVersion=8),log=(enabled=false)"}}
 {"t":{"$date":"2020-03-05T18:40:26.267+0000"},"s":"D1","c":"STORAGE", "id":22258,"ctx":"IndexBuildsCoordinatorMongod-1","msg":"created temporary record store:  {rs_getIdent}","attr":{"rs_getIdent":"internal-3207-8434647472929354996"}}
 {"t":{"$date":"2020-03-05T18:40:26.267+0000"},"s":"D1","c":"STORAGE", "id":20907,"ctx":"IndexBuildsCoordinatorMongod-1","msg":"{coll_ns}: clearing plan         cache - collection info cache reset","attr":{"coll_ns":"pymongo_test.test"}}
 {"t":{"$date":"2020-03-05T18:40:26.267+0000"},"s":"I", "c":"INDEX",   "id":20384,"ctx":"IndexBuildsCoordinatorMongod-1","msg":"index build: starting on {ns}    properties: {descriptor} using method: {method}","attr":{"ns":"pymongo_test.test","descriptor":{"v":2,"key":{"a":-1},"name":"a_-1"},"method":"Hybrid"}}
 {"t":{"$date":"2020-03-05T18:40:26.267+0000"},"s":"I", "c":"INDEX",   "id":20385,"ctx":"IndexBuildsCoordinatorMongod-1","msg":"build may temporarily use up to  {eachIndexBuildMaxMemoryUsageBytes_1024_1024} megabytes of RAM","attr":{"eachIndexBuildMaxMemoryUsageBytes_1024_1024":200}}
 {"t":{"$date":"2020-03-05T18:40:26.267+0000"},"s":"I", "c":"STORAGE", "id":20346,"ctx":"IndexBuildsCoordinatorMongod-1","msg":"Index build initialized:         {buildUUID}: {nss} ({collection_uuid} ): indexes: {indexes_size}","attr":{"buildUUID":{"uuid":{"$uuid":"92da4727-7623-46f4-ac2e-1856a5edba91"}},"nss":          "pymongo_test.test","collection_uuid":{"uuid":{"$uuid":"68d7d0de-cc78-441a-8bf9-85b28c69e5e4"}},"indexes_size":1}}
 {"t":{"$date":"2020-03-05T18:40:26.267+0000"},"s":"I", "c":"INDEX",   "id":20439,"ctx":"conn509","msg":"Waiting for index build to complete: {buildUUID}",      "attr":{"buildUUID":{"uuid":{"$uuid":"92da4727-7623-46f4-ac2e-1856a5edba91"}}}}
{"t":{"$date":"2020-03-05T18:40:26.267+0000"},"s":"I", "c":"INDEX",   "id":20391,"ctx":"IndexBuildsCoordinatorMongod-1","msg":"index build: collection scan done. scanned {n} total records in {t_seconds} seconds","attr":{"n":1,"t_seconds":0}}
{"t":{"$date":"2020-03-05T18:40:26.267+0000"},"s":"D1","c":"INDEX",   "id":20392,"ctx":"IndexBuildsCoordinatorMongod-1","msg":"index build: inserting from external sorter into index: {entry_descriptor_indexName}","attr":{"entry_descriptor_indexName":"a_-1"}}
{"t":{"$date":"2020-03-05T18:40:26.268+0000"},"s":"I", "c":"INDEX",   "id":20685,"ctx":"IndexBuildsCoordinatorMongod-1","msg":"index build: inserted {bulk_getKeysInserted} keys from external sorter into index in {timer_seconds} seconds","attr":{"bulk_getKeysInserted":1,"timer_seconds":0}}
{"t":{"$date":"2020-03-05T18:40:26.270+0000"},"s":"D1","c":"INDEX",   "id":20689,"ctx":"IndexBuildsCoordinatorMongod-1","msg":"index build: drain applied {numApplied_appliedAtStart} side writes (inserted: {totalInserted}, deleted: {totalDeleted}) for '{indexCatalogEntry_descriptor_indexName}' in {timer_millis} ms","attr":{"numApplied_appliedAtStart":0,"totalInserted":0,"totalDeleted":0,"indexCatalogEntry_descriptor_indexName":"a_-1","timer_millis":0}}
{"t":{"$date":"2020-03-05T18:40:26.270+0000"},"s":"D1","c":"INDEX",   "id":20689,"ctx":"IndexBuildsCoordinatorMongod-1","msg":"index build: drain applied {numApplied_appliedAtStart} side writes (inserted: {totalInserted}, deleted: {totalDeleted}) for '{indexCatalogEntry_descriptor_indexName}' in {timer_millis} ms","attr":{"numApplied_appliedAtStart":0,"totalInserted":0,"totalDeleted":0,"indexCatalogEntry_descriptor_indexName":"a_-1","timer_millis":0}}
{"t":{"$date":"2020-03-05T18:40:26.271+0000"},"s":"D1","c":"COMMAND", "id":3856208,"ctx":"IndexBuildsCoordinatorMongod-1","msg":"Received voteCommitIndexBuild request for index build: {builduuid}, from host: {host} ","attr":{"builduuid":{"uuid":{"$uuid":"92da4727-7623-46f4-ac2e-1856a5edba91"}},"host":"localhost:27019"}}
{"t":{"$date":"2020-03-05T18:40:26.273+0000"},"s":"D1","c":"REPL",    "id":21337,"ctx":"IndexBuildsCoordinatorMongod-1","msg":"Required snapshot optime: {opTime} is not yet part of the current 'committed' snapshot: {currentCommittedSnapshotOpTime}","attr":{"opTime":{"ts":{"$timestamp":{"t":1583433626,"i":18}},"t":3},"currentCommittedSnapshotOpTime":{"ts":{"$timestamp":{"t":1583433625,"i":144}},"t":3}}}

I've attached the full logs as well: server-logs-PYTHON-2153.zip

To reproduce

  • start a v4.5.0-24-gb801dec 3 node replica set with one node running on port 27017.
  • clone pymongo: git clone git@github.com:mongodb/mongo-python-driver.git && cd mongo-python-driver
  • Run the test: python setup.py test -s test.test_read_write_concern_spec.TestReadWriteConcernSpec.test_raise_wtimeout

Note: This test passes on MongoDB 4.3.4 and lower.



 Comments   
Comment by Benety Goh [ 02/Apr/20 ]

For the affected python test, we are applying a workaround that uses an optimization for empty collections implemented in SERVER-45201.

Comment by Benety Goh [ 02/Apr/20 ]

The wtimeout write concern option is not the most ideal way to impose a timeout on a createIndexes command, especially given the new behavior introduced in SERVER-45001.

A better mechanism would be to utilize the maxTimeMS option. An example of using the createIndexes command with maxTimeMS can be found in the max_time_ms.js test:

        // "createIndexes" command.
        assert.commandWorked(t.runCommand(
            "createIndexes", {indexes: [{key: {x: 1}, name: "x_1"}], maxTimeMS: 60 * 1000}));

Comment by Benety Goh [ 31/Mar/20 ]

We previously encountered a similar problem in the python drivers test suite with the dropDatabase command but solution we applied in SERVER-34776 may not be applicable in this case to the createIndexes command.

Comment by Benety Goh [ 30/Mar/20 ]

Starting SERVER-45001, creating an index in a replica set with will include additional internal majority writes to coordinate the completion of the index build between the primary and the secondaries. The test setup described here prevents the secondaries from applying those internal majority writes. As result, the primary will not be able to complete the createIndexes operation before enforcing/checking the provided write concern.

If we wish to still test the createIndexes command using the current setup, we can add a

{ commitQuorum: 0 }

to the createIndexes command in the test as a workaround:

db.runCommand({createIndexes: 'mycoll', indexes: [{v:2, key: {d: 1}, name: 'd_1'}], commitQuorum: 0, writeConcern: {w: 3, wtimeout: 1}})

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