[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.