-
Type: Bug
-
Resolution: Works as Designed
-
Priority: Major - P3
-
None
-
Affects Version/s: None
-
Component/s: None
-
None
-
ALL
-
Execution Team 2020-04-06
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.
- causes
-
PYTHON-2153 test_raise_wtimeout hangs on 4.5 latest
- Closed
- is related to
-
SERVER-34776 dropDatabase should respect user provided writeConcern
- Closed
-
SERVER-45201 Implicit collection creation from createIndexes can stall replication on secondaries by circumventing thread pool on primary
- Closed
-
SERVER-45001 enable commit quorum for two phase index builds by default
- Closed