[CDRIVER-4268] /transactions/legacy/mongos-recovery-token failing with server selection timeout Created: 25/Jan/22  Updated: 02/Oct/23

Status: Backlog
Project: C Driver
Component/s: None
Affects Version/s: None
Fix Version/s: None

Type: Task Priority: Major - P3
Reporter: Kevin Albertson Assignee: Unassigned
Resolution: Unresolved Votes: 0
Labels: failing-on-waterfall, flaky-tests
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Duplicate
is duplicated by CDRIVER-4252 "commitTransaction retry fails on new... Closed
Epic Link: Stabilize Evergreen

 Description   

Example failure

With logs:

[2022/01/24 16:17:48.535] Begin /transactions/legacy/mongos-recovery-token, seed 3942742901
[2022/01/24 16:17:49.991]   - commitTransaction explicit retries include recoveryToken
[2022/01/24 16:17:49.991] 2022/01/24 16:17:49.0990: [ 9332]:    DEBUG:       mongoc:      running operation startTransaction : { "name" : "startTransaction", "object" : "session0" }
[2022/01/24 16:17:49.991] 2022/01/24 16:17:49.0991: [ 9332]:    DEBUG:       mongoc:      running operation insertOne : { "name" : "insertOne", "object" : "collection", "arguments" : { "session" : "session0", "document" : { "_id" : 1 } }, "result" : { "insertedId" : 1 } }
[2022/01/24 16:17:49.991] { "insert" : "test", "ordered" : true, "$db" : "transaction-tests", "lsid" : { "id" : { "$binary" : { "base64" : "1poQUMOfSkihFPeY/IjJFw==", "subType" : "04" } } }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1643041069, "i" : 34 } }, "signature" : { "hash" : { "$binary" : { "base64" : "Ht2GopqpL+7mjSNUP6yIYdr2CBc=", "subType" : "00" } }, "keyId" : { "$numberLong" : "7056804178416369674" } } }, "startTransaction" : true, "txnNumber" : { "$numberLong" : "1" }, "autocommit" : false, "documents" : [ { "_id" : { "$numberInt" : "1" } } ] }
[2022/01/24 16:17:49.993] 2022/01/24 16:17:49.0992: [ 9332]:    DEBUG:       mongoc: <-- COMMAND SUCCEEDED: { "n" : { "$numberInt" : "1" }, "ok" : { "$numberDouble" : "1.0" }, "operationTime" : { "$timestamp" : { "t" : 1643041069, "i" : 42 } }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1643041069, "i" : 44 } }, "signature" : { "hash" : { "$binary" : { "base64" : "Ht2GopqpL+7mjSNUP6yIYdr2CBc=", "subType" : "00" } }, "keyId" : { "$numberLong" : "7056804178416369674" } } }, "recoveryToken" : { "recoveryShardId" : "sh01" } }
[2022/01/24 16:17:49.993] 2022/01/24 16:17:49.0993: [ 9332]:    DEBUG:       mongoc:      running operation commitTransaction : { "name" : "commitTransaction", "object" : "session0" }
[2022/01/24 16:17:49.993] { "commitTransaction" : { "$numberInt" : "1" }, "recoveryToken" : { "recoveryShardId" : "sh01" }, "$db" : "admin", "lsid" : { "id" : { "$binary" : { "base64" : "1poQUMOfSkihFPeY/IjJFw==", "subType" : "04" } } }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1643041069, "i" : 44 } }, "signature" : { "hash" : { "$binary" : { "base64" : "Ht2GopqpL+7mjSNUP6yIYdr2CBc=", "subType" : "00" } }, "keyId" : { "$numberLong" : "7056804178416369674" } } }, "txnNumber" : { "$numberLong" : "1" }, "autocommit" : false }
[2022/01/24 16:17:49.995] 2022/01/24 16:17:49.0994: [ 9332]:    DEBUG:       mongoc: <-- COMMAND SUCCEEDED: { "ok" : { "$numberDouble" : "1.0" }, "operationTime" : { "$timestamp" : { "t" : 1643041069, "i" : 45 } }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1643041069, "i" : 45 } }, "signature" : { "hash" : { "$binary" : { "base64" : "Ht2GopqpL+7mjSNUP6yIYdr2CBc=", "subType" : "00" } }, "keyId" : { "$numberLong" : "7056804178416369674" } } }, "recoveryToken" : { "recoveryShardId" : "sh01" } }
[2022/01/24 16:17:49.995] 2022/01/24 16:17:49.0994: [ 9332]:    DEBUG:       mongoc:      running operation commitTransaction : { "name" : "commitTransaction", "object" : "session0" }
[2022/01/24 16:17:49.995] { "commitTransaction" : { "$numberInt" : "1" }, "recoveryToken" : { "recoveryShardId" : "sh01" }, "$db" : "admin", "lsid" : { "id" : { "$binary" : { "base64" : "1poQUMOfSkihFPeY/IjJFw==", "subType" : "04" } } }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1643041069, "i" : 45 } }, "signature" : { "hash" : { "$binary" : { "base64" : "Ht2GopqpL+7mjSNUP6yIYdr2CBc=", "subType" : "00" } }, "keyId" : { "$numberLong" : "7056804178416369674" } } }, "writeConcern" : { "w" : "majority", "wtimeout" : { "$numberLong" : "10000" } }, "txnNumber" : { "$numberLong" : "1" }, "autocommit" : false }
[2022/01/24 16:17:49.997] 2022/01/24 16:17:49.0997: [ 9332]:    DEBUG:       mongoc: <-- COMMAND SUCCEEDED: { "ok" : { "$numberDouble" : "1.0" }, "operationTime" : { "$timestamp" : { "t" : 1643041069, "i" : 45 } }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1643041069, "i" : 45 } }, "signature" : { "hash" : { "$binary" : { "base64" : "Ht2GopqpL+7mjSNUP6yIYdr2CBc=", "subType" : "00" } }, "keyId" : { "$numberLong" : "7056804178416369674" } } }, "recoveryToken" : { "recoveryShardId" : "sh01" } }
[2022/01/24 16:17:49.997] 2022/01/24 16:17:49.0997: [ 9332]:    DEBUG:       mongoc:      running operation commitTransaction : { "name" : "commitTransaction", "object" : "session0" }
[2022/01/24 16:17:49.997] { "commitTransaction" : { "$numberInt" : "1" }, "recoveryToken" : { "recoveryShardId" : "sh01" }, "$db" : "admin", "lsid" : { "id" : { "$binary" : { "base64" : "1poQUMOfSkihFPeY/IjJFw==", "subType" : "04" } } }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1643041069, "i" : 45 } }, "signature" : { "hash" : { "$binary" : { "base64" : "Ht2GopqpL+7mjSNUP6yIYdr2CBc=", "subType" : "00" } }, "keyId" : { "$numberLong" : "7056804178416369674" } } }, "writeConcern" : { "w" : "majority", "wtimeout" : { "$numberLong" : "10000" } }, "txnNumber" : { "$numberLong" : "1" }, "autocommit" : false }
[2022/01/24 16:17:50.679] 2022/01/24 16:17:49.0998: [ 9332]:    DEBUG:       mongoc: <-- COMMAND SUCCEEDED: { "ok" : { "$numberDouble" : "1.0" }, "operationTime" : { "$timestamp" : { "t" : 1643041069, "i" : 45 } }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1643041069, "i" : 45 } }, "signature" : { "hash" : { "$binary" : { "base64" : "Ht2GopqpL+7mjSNUP6yIYdr2CBc=", "subType" : "00" } }, "keyId" : { "$numberLong" : "7056804178416369674" } } }, "recoveryToken" : { "recoveryShardId" : "sh01" } }
[2022/01/24 16:17:50.679]   - commitTransaction retry succeeds on new mongos
[2022/01/24 16:17:50.936] 2022/01/24 16:17:50.0935: [ 9332]:    DEBUG:       mongoc:      running operation startTransaction : { "name" : "startTransaction", "object" : "session0", "arguments" : { "options" : { "writeConcern" : { "w" : "majority" } } } }
[2022/01/24 16:17:50.936] 2022/01/24 16:17:50.0935: [ 9332]:    DEBUG:       mongoc:      running operation insertOne : { "name" : "insertOne", "object" : "collection", "arguments" : { "session" : "session0", "document" : { "_id" : 1 } }, "result" : { "insertedId" : 1 } }
[2022/01/24 16:17:50.936] { "insert" : "test", "ordered" : true, "$db" : "transaction-tests", "lsid" : { "id" : { "$binary" : { "base64" : "u2E/bgdcRo+HQa4S+9ewyQ==", "subType" : "04" } } }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1643041070, "i" : 39 } }, "signature" : { "hash" : { "$binary" : { "base64" : "yVwOQDvrh9dozMYYfV9aPdZI+8k=", "subType" : "00" } }, "keyId" : { "$numberLong" : "7056804178416369674" } } }, "startTransaction" : true, "txnNumber" : { "$numberLong" : "1" }, "autocommit" : false, "documents" : [ { "_id" : { "$numberInt" : "1" } } ] }
[2022/01/24 16:17:51.023] 2022/01/24 16:17:50.0937: [ 9332]:    DEBUG:       mongoc: <-- COMMAND SUCCEEDED: { "n" : { "$numberInt" : "1" }, "ok" : { "$numberDouble" : "1.0" }, "operationTime" : { "$timestamp" : { "t" : 1643041070, "i" : 47 } }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1643041070, "i" : 49 } }, "signature" : { "hash" : { "$binary" : { "base64" : "yVwOQDvrh9dozMYYfV9aPdZI+8k=", "subType" : "00" } }, "keyId" : { "$numberLong" : "7056804178416369674" } } }, "recoveryToken" : { "recoveryShardId" : "sh01" } }
[2022/01/24 16:17:51.023] 2022/01/24 16:17:50.0938: [ 9332]:    DEBUG:       mongoc:      running operation targetedFailPoint : { "name" : "targetedFailPoint", "object" : "testRunner", "arguments" : { "session" : "session0", "failPoint" : { "configureFailPoint" : "failCommand", "mode" : { "times" : 1 }, "data" : { "failCommands" : [ "commitTransaction" ], "writeConcernError" : { "code" : 91, "errmsg" : "Replication is being shut down", "errorLabels" : [ "RetryableWriteError" ] } } } } }
[2022/01/24 16:17:51.023] 2022/01/24 16:17:51.0023: [ 9332]:    DEBUG:       mongoc:      running operation commitTransaction : { "name" : "commitTransaction", "object" : "session0" }
[2022/01/24 16:17:51.023] { "commitTransaction" : { "$numberInt" : "1" }, "recoveryToken" : { "recoveryShardId" : "sh01" }, "$db" : "admin", "lsid" : { "id" : { "$binary" : { "base64" : "u2E/bgdcRo+HQa4S+9ewyQ==", "subType" : "04" } } }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1643041070, "i" : 49 } }, "signature" : { "hash" : { "$binary" : { "base64" : "yVwOQDvrh9dozMYYfV9aPdZI+8k=", "subType" : "00" } }, "keyId" : { "$numberLong" : "7056804178416369674" } } }, "writeConcern" : { "w" : "majority" }, "txnNumber" : { "$numberLong" : "1" }, "autocommit" : false }
[2022/01/24 16:17:51.026] 2022/01/24 16:17:51.0025: [ 9332]:    DEBUG:       mongoc: <-- COMMAND SUCCEEDED: { "ok" : { "$numberDouble" : "1.0" }, "writeConcernError" : { "code" : { "$numberInt" : "91" }, "errmsg" : "Replication is being shut down", "errorLabels" : [ "RetryableWriteError" ] }, "operationTime" : { "$timestamp" : { "t" : 1643041071, "i" : 1 } }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1643041071, "i" : 1 } }, "signature" : { "hash" : { "$binary" : { "base64" : "rVo2zPwJ3GobyJFZe1kTyo0pYmM=", "subType" : "00" } }, "keyId" : { "$numberLong" : "7056804178416369674" } } }, "recoveryToken" : { "recoveryShardId" : "sh01" } }
[2022/01/24 16:17:51.026] { "commitTransaction" : { "$numberInt" : "1" }, "recoveryToken" : { "recoveryShardId" : "sh01" }, "$db" : "admin", "lsid" : { "id" : { "$binary" : { "base64" : "u2E/bgdcRo+HQa4S+9ewyQ==", "subType" : "04" } } }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1643041071, "i" : 1 } }, "signature" : { "hash" : { "$binary" : { "base64" : "rVo2zPwJ3GobyJFZe1kTyo0pYmM=", "subType" : "00" } }, "keyId" : { "$numberLong" : "7056804178416369674" } } }, "writeConcern" : { "w" : "majority", "wtimeout" : { "$numberLong" : "10000" } }, "txnNumber" : { "$numberLong" : "1" }, "autocommit" : false }
[2022/01/24 16:17:51.693] 2022/01/24 16:17:51.0027: [ 9332]:    DEBUG:       mongoc: <-- COMMAND SUCCEEDED: { "ok" : { "$numberDouble" : "1.0" }, "operationTime" : { "$timestamp" : { "t" : 1643041071, "i" : 1 } }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1643041071, "i" : 1 } }, "signature" : { "hash" : { "$binary" : { "base64" : "rVo2zPwJ3GobyJFZe1kTyo0pYmM=", "subType" : "00" } }, "keyId" : { "$numberLong" : "7056804178416369674" } } }, "recoveryToken" : {  } }
[2022/01/24 16:17:51.693]   - commitTransaction retry fails on new mongos
[2022/01/24 16:17:51.950] 2022/01/24 16:17:51.0948: [ 9332]:    DEBUG:       mongoc:      running operation startTransaction : { "name" : "startTransaction", "object" : "session0" }
[2022/01/24 16:17:51.950] 2022/01/24 16:17:51.0950: [ 9332]:    DEBUG:       mongoc:      running operation insertOne : { "name" : "insertOne", "object" : "collection", "arguments" : { "session" : "session0", "document" : { "_id" : 1 } }, "result" : { "insertedId" : 1 } }
[2022/01/24 16:17:51.950] { "insert" : "test", "ordered" : true, "$db" : "transaction-tests", "lsid" : { "id" : { "$binary" : { "base64" : "+w/Zbrq4Q8SHGcT9fj9mcA==", "subType" : "04" } } }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1643041071, "i" : 46 } }, "signature" : { "hash" : { "$binary" : { "base64" : "rVo2zPwJ3GobyJFZe1kTyo0pYmM=", "subType" : "00" } }, "keyId" : { "$numberLong" : "7056804178416369674" } } }, "startTransaction" : true, "txnNumber" : { "$numberLong" : "1" }, "autocommit" : false, "documents" : [ { "_id" : { "$numberInt" : "1" } } ] }
[2022/01/24 16:17:52.054] 2022/01/24 16:17:51.0951: [ 9332]:    DEBUG:       mongoc: <-- COMMAND SUCCEEDED: { "n" : { "$numberInt" : "1" }, "ok" : { "$numberDouble" : "1.0" }, "operationTime" : { "$timestamp" : { "t" : 1643041071, "i" : 44 } }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1643041071, "i" : 46 } }, "signature" : { "hash" : { "$binary" : { "base64" : "rVo2zPwJ3GobyJFZe1kTyo0pYmM=", "subType" : "00" } }, "keyId" : { "$numberLong" : "7056804178416369674" } } }, "recoveryToken" : { "recoveryShardId" : "sh01" } }
[2022/01/24 16:17:52.054] 2022/01/24 16:17:51.0952: [ 9332]:    DEBUG:       mongoc:      running operation targetedFailPoint : { "name" : "targetedFailPoint", "object" : "testRunner", "arguments" : { "session" : "session0", "failPoint" : { "configureFailPoint" : "failCommand", "mode" : { "times" : 7 }, "data" : { "failCommands" : [ "commitTransaction", "isMaster", "hello" ], "closeConnection" : true } } } }
[2022/01/24 16:17:52.054] 2022/01/24 16:17:52.0053: [ 9332]:    DEBUG:       mongoc:      running operation commitTransaction : { "name" : "commitTransaction", "object" : "session0", "result" : { "errorLabelsContain" : [ "TransientTransactionError" ], "errorLabelsOmit" : [ "UnknownTransactionCommitResult" ], "errorCodeName" : "NoSuchTransaction" } }
[2022/01/24 16:17:52.054] { "commitTransaction" : { "$numberInt" : "1" }, "recoveryToken" : { "recoveryShardId" : "sh01" }, "$db" : "admin", "lsid" : { "id" : { "$binary" : { "base64" : "+w/Zbrq4Q8SHGcT9fj9mcA==", "subType" : "04" } } }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1643041071, "i" : 46 } }, "signature" : { "hash" : { "$binary" : { "base64" : "rVo2zPwJ3GobyJFZe1kTyo0pYmM=", "subType" : "00" } }, "keyId" : { "$numberLong" : "7056804178416369674" } } }, "txnNumber" : { "$numberLong" : "1" }, "autocommit" : false }
[2022/01/24 16:17:52.055] 2022/01/24 16:17:52.0054: [ 9332]:    DEBUG:       mongoc: <-- commitTransaction COMMAND FAILED: Failed to send "commitTransaction" command with database "admin": Failed to read 4 bytes: socket error or timeout
[2022/01/24 16:17:52.055] REPLY: { }
[2022/01/24 16:17:52.055] { "commitTransaction" : { "$numberInt" : "1" }, "recoveryToken" : { "recoveryShardId" : "sh01" }, "$db" : "admin", "lsid" : { "id" : { "$binary" : { "base64" : "+w/Zbrq4Q8SHGcT9fj9mcA==", "subType" : "04" } } }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1643041071, "i" : 46 } }, "signature" : { "hash" : { "$binary" : { "base64" : "rVo2zPwJ3GobyJFZe1kTyo0pYmM=", "subType" : "00" } }, "keyId" : { "$numberLong" : "7056804178416369674" } } }, "writeConcern" : { "w" : "majority", "wtimeout" : { "$numberLong" : "10000" } }, "txnNumber" : { "$numberLong" : "1" }, "autocommit" : false }
[2022/01/24 16:18:11.134] error calling legacy hello: 'No suitable servers found: `serverselectiontimeoutms` timed out: [Failed to receive length header from server. calling hello on 'localhost:27017']'
[2022/01/24 16:18:11.134] URI = mongodb://bob:pwd123@localhost:27017/?ssl=true
[2022/01/24 16:18:11.183] Aborted
[2022/01/24 16:18:11.183] Command failed: command encountered problem: error waiting on process 'f5427c37-f5f7-412b-9d37-83515202b1ce': exit status 134
[2022/01/24 16:18:11.183] Task completed - FAILURE.



 Comments   
Comment by Kevin Albertson [ 02/Oct/23 ]

Test was unskipped and run in a patch build: https://spruce.mongodb.com/task/mongo_c_driver_sanitizers_matrix_asan_asan_sasl_cyrus_openssl_ubuntu1804_clang_test_6.0_sharded_auth_patch_86037268ccaab73a841219225d49a0c32c5024c4_6516cf2ad1fe07b7c48d43d8_23_09_29_13_20_45/logs?execution=0. Resulted in failure.

[2023/09/29 13:45:08.714]   "results": [
[2023/09/29 13:45:09.306]   - commitTransaction explicit retries include recoveryToken SKIPPED by MONGOC_JSON_SUBTEST
[2023/09/29 13:45:09.306]   - commitTransaction retry succeeds on new mongos SKIPPED by MONGOC_JSON_SUBTEST
[2023/09/29 13:45:09.827] Begin /transactions/legacy/mongos-recovery-token, seed 1183908751
[2023/09/29 13:45:09.827]   - commitTransaction retry fails on new mongos
[2023/09/29 13:45:10.032] 2023/09/29 13:45:10.0031: [30308]:    DEBUG:       mongoc:      running operation startTransaction : { "name" : "startTransaction", "object" : "session0" }
[2023/09/29 13:45:10.032] 2023/09/29 13:45:10.0031: [30308]:    DEBUG:       mongoc:      running operation insertOne : { "name" : "insertOne", "object" : "collection", "arguments" : { "session" : "session0", "document" : { "_id" : 1 } }, "result" : { "insertedId" : 1 } }
[2023/09/29 13:45:10.032] { "insert" : "test", "ordered" : true, "$db" : "transaction-tests", "lsid" : { "id" : { "$binary" : { "base64" : "6ENQLtrJT6uaACYAEqOa6A==", "subType" : "04" } } }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1695995109, "i" : 1 } }, "signature" : { "hash" : { "$binary" : { "base64" : "21eggsyRR9Cn3tk42o4l5QAJh9c=", "subType" : "00" } }, "keyId" : { "$numberLong" : "7284243381302067225" } } }, "startTransaction" : true, "txnNumber" : { "$numberLong" : "1" }, "autocommit" : false, "documents" : [ { "_id" : { "$numberInt" : "1" } } ] }
[2023/09/29 13:45:10.104] 2023/09/29 13:45:10.0035: [30308]:    DEBUG:       mongoc: <-- COMMAND SUCCEEDED: { "n" : { "$numberInt" : "1" }, "ok" : { "$numberDouble" : "1.0" }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1695995109, "i" : 6 } }, "signature" : { "hash" : { "$binary" : { "base64" : "21eggsyRR9Cn3tk42o4l5QAJh9c=", "subType" : "00" } }, "keyId" : { "$numberLong" : "7284243381302067225" } } }, "operationTime" : { "$timestamp" : { "t" : 1695995109, "i" : 6 } }, "recoveryToken" : { "recoveryShardId" : "sh02" } }
[2023/09/29 13:45:10.104] 2023/09/29 13:45:10.0035: [30308]:    DEBUG:       mongoc:      running operation targetedFailPoint : { "name" : "targetedFailPoint", "object" : "testRunner", "arguments" : { "session" : "session0", "failPoint" : { "configureFailPoint" : "failCommand", "mode" : { "times" : 7 }, "data" : { "failCommands" : [ "commitTransaction", "isMaster", "hello" ], "closeConnection" : true } } } }
[2023/09/29 13:45:10.104] 2023/09/29 13:45:10.0104: [30308]:    DEBUG:       mongoc:      running operation commitTransaction : { "name" : "commitTransaction", "object" : "session0", "result" : { "errorLabelsContain" : [ "TransientTransactionError" ], "errorLabelsOmit" : [ "UnknownTransactionCommitResult" ], "errorCodeName" : "NoSuchTransaction" } }
[2023/09/29 13:45:10.104] { "commitTransaction" : { "$numberInt" : "1" }, "recoveryToken" : { "recoveryShardId" : "sh02" }, "$db" : "admin", "lsid" : { "id" : { "$binary" : { "base64" : "6ENQLtrJT6uaACYAEqOa6A==", "subType" : "04" } } }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1695995109, "i" : 6 } }, "signature" : { "hash" : { "$binary" : { "base64" : "21eggsyRR9Cn3tk42o4l5QAJh9c=", "subType" : "00" } }, "keyId" : { "$numberLong" : "7284243381302067225" } } }, "txnNumber" : { "$numberLong" : "1" }, "autocommit" : false }
[2023/09/29 13:45:10.105] 2023/09/29 13:45:10.0104: [30308]:    DEBUG:      cluster: could not read message length, stream probably closed or timed out
[2023/09/29 13:45:10.105] 2023/09/29 13:45:10.0104: [30308]:    DEBUG:       mongoc: <-- commitTransaction COMMAND FAILED: Failed to send "commitTransaction" command with database "admin": Failed to read 4 bytes: socket error or timeout
[2023/09/29 13:45:10.105] REPLY: { }
[2023/09/29 13:45:10.105] { "commitTransaction" : { "$numberInt" : "1" }, "recoveryToken" : { "recoveryShardId" : "sh02" }, "$db" : "admin", "lsid" : { "id" : { "$binary" : { "base64" : "6ENQLtrJT6uaACYAEqOa6A==", "subType" : "04" } } }, "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1695995109, "i" : 6 } }, "signature" : { "hash" : { "$binary" : { "base64" : "21eggsyRR9Cn3tk42o4l5QAJh9c=", "subType" : "00" } }, "keyId" : { "$numberLong" : "7284243381302067225" } } }, "writeConcern" : { "w" : "majority", "wtimeout" : { "$numberLong" : "10000" } }, "txnNumber" : { "$numberLong" : "1" }, "autocommit" : false }
[2023/09/29 13:45:29.165] test error in: /data/mci/84309b76b8ad63f914d175a9cf6e43d9/mongoc/src/libmongoc/tests/test-libmongoc.c 924:call_hello_with_host_and_port()
[2023/09/29 13:45:29.165] error calling legacy hello: 'No suitable servers found: `serverselectiontimeoutms` timed out: [Failed to receive length header from server. calling hello on 'localhost:27017']'
[2023/09/29 13:45:29.165] 2023/09/29 13:45:10.0112: [30308]:    DEBUG:       mongoc: <-- commitTransaction COMMAND FAILED: Recovering the transaction's outcome found the transaction aborted
[2023/09/29 13:45:29.165] REPLY: { "errorLabels" : [ "TransientTransactionError" ], "ok" : { "$numberDouble" : "0.0" }, "errmsg" : "Recovering the transaction's outcome found the transaction aborted", "code" : { "$numberInt" : "251" }, "codeName" : "NoSuchTransaction", "$clusterTime" : { "clusterTime" : { "$timestamp" : { "t" : 1695995110, "i" : 1 } }, "signature" : { "hash" : { "$binary" : { "base64" : "AleriwROuRmEGCQE4hFOKNuP4bw=", "subType" : "00" } }, "keyId" : { "$numberLong" : "7284243381302067225" } } }, "operationTime" : { "$timestamp" : { "t" : 1695995110, "i" : 1 } }, "recoveryToken" : {  } }

Leaving in "Backlog".

Generated at Wed Feb 07 21:20:27 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.