Fixes caliper hang of unfinished transactions (#1342)

This addresses a long standing issue in caliper where a round will hang waiting for unfinished transactions that have actually finished but not been recorded. It also addresses an issue where the fabric connectors try to change the time_create value of a TxStatus but in fact actually doesn't change the creation time. closes #1068 closes #1340 Signed-off-by: D <[email protected]>
hyperledger-caliper · May 17, 2022 · 2fd8925 · 2fd8925
1 parent df1b96c
commit 2fd8925
Show file tree

Hide file tree

Showing 9 changed files with 148 additions and 13 deletions.
diff --git a/packages/caliper-core/lib/common/core/connector-base.js b/packages/caliper-core/lib/common/core/connector-base.js
@@ -116,7 +116,7 @@ class ConnectorBase extends ConnectorInterface {
                 failureResult.SetStatusFail();
                 failureResult.SetVerification(true);
                 failureResult.SetResult('');
-                failureResult.Set('time_create', creationTime);
+                failureResult.SetTimeCreate(creationTime);
                 return failureResult;
             }
 

diff --git a/packages/caliper-core/lib/common/core/transaction-statistics-collector.js b/packages/caliper-core/lib/common/core/transaction-statistics-collector.js
@@ -73,7 +73,6 @@ class TransactionStatisticsCollector {
      * @private
      */
     _updateStatistics(txResult) {
-        this.stats.txCounters.totalFinished +=1;
 
         // updating create time stats
         let createTime = txResult.GetTimeCreate();
@@ -398,15 +397,19 @@ class TransactionStatisticsCollector {
             return;
         }
 
+        // irrespective of when a result finished it should be recorded.
+        this.stats.txCounters.totalFinished = Array.isArray(results) ? this.stats.txCounters.totalFinished + results.length : this.stats.txCounters.totalFinished + 1;
+
+        // only process the results if the finished transaction was received on or after the round started
         if (Array.isArray(results)) {
-            let relevantResults = results.filter(r => r.GetTimeCreate() > this.getRoundStartTime());
+            let relevantResults = results.filter(r => r.GetTimeCreate() >= this.getRoundStartTime());
             for (let result of relevantResults) {
                 this._updateStatistics(result);
             }
             for (let subcollector of this.subCollectors) {
                 subcollector.txFinished(relevantResults);
             }
-        } else if (results.GetTimeCreate() > this.getRoundStartTime()) {
+        } else if (results.GetTimeCreate() >= this.getRoundStartTime()) {
             this._updateStatistics(results);
             for (let subcollector of this.subCollectors) {
                 subcollector.txFinished(results);

diff --git a/packages/caliper-core/lib/common/core/transaction-status.js b/packages/caliper-core/lib/common/core/transaction-status.js
@@ -86,6 +86,14 @@ class TxStatus {
         return this.status.time_create;
     }
 
+    /**
+     * Set a new creation time
+     * @param {int} newCreationTime new creation time in ms
+     */
+    SetTimeCreate(newCreationTime) {
+        this.status.time_create = newCreationTime;
+    }
+
     /**
      * Getter of the tx final time
      * @return {int} final time in ms
@@ -177,7 +185,8 @@ class TxStatus {
     }
 
     /**
-     * Set any key/value
+     * Set a custom key/value. This sets a key with the custom subsection of this
+     * status instance and cannot be used to modify internal keys such as `time_create` or `time_final` for example.
      * @param {string} key key
      * @param {any} value value
      */
@@ -186,7 +195,7 @@ class TxStatus {
     }
 
     /**
-     * Get any specified element
+     * Get a custom value from the key
      * @param {string} key key
      * @return {any} value
      */

diff --git a/packages/caliper-core/test/core/transaction-statistics-collector.js b/packages/caliper-core/test/core/transaction-statistics-collector.js
@@ -0,0 +1,86 @@
+/*
+* Licensed under the Apache License, Version 2.0 (the "License");
+* you may not use this file except in compliance with the License.
+* You may obtain a copy of the License at
+*
+* http://www.apache.org/licenses/LICENSE-2.0
+*
+* Unless required by applicable law or agreed to in writing, software
+* distributed under the License is distributed on an "AS IS" BASIS,
+* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+* See the License for the specific language governing permissions and
+* limitations under the License.
+*/
+
+'use strict';
+
+const chai = require('chai');
+chai.should();
+
+const TransactionStatisticsCollector = require('../../lib/common/core/transaction-statistics-collector');
+const TxStatus = require('../../lib/common/core/transaction-status');
+
+describe('the transaction statistics collector', () => {
+    const createSuccessfulTxStatus = (creationTimeAfterRoundStart) => {
+        const txStatus = new TxStatus('id');
+        txStatus.SetTimeCreate(txStatsCollector.getRoundStartTime() + creationTimeAfterRoundStart);
+        txStatus.SetStatusSuccess();
+        return txStatus;
+    };
+
+    let txStatsCollector;
+    beforeEach(() => {
+        txStatsCollector = new TransactionStatisticsCollector(1,1,'');
+        txStatsCollector.activate();
+    })
+
+    it('should register as finished a single finished transaction while active irrespective of time of creation', () => {
+        txStatsCollector.txSubmitted(3);
+
+        // test if it finishes after the round start time
+        txStatsCollector.txFinished(createSuccessfulTxStatus(60000));
+        txStatsCollector.getTotalFinishedTx().should.equal(1);
+
+        // test if it finishes when the round started
+        txStatsCollector.txFinished(createSuccessfulTxStatus(0));
+        txStatsCollector.getTotalFinishedTx().should.equal(2);
+
+        // test if it finishes before the round start time
+        txStatsCollector.txFinished(createSuccessfulTxStatus(-60000));
+        txStatsCollector.getTotalFinishedTx().should.equal(3);
+
+    });
+
+    it('should register multiple transactions as finished while active irrespective of time of creation', () => {
+        txStatsCollector.txSubmitted(3);
+        txStatsCollector.txFinished([createSuccessfulTxStatus(60000), createSuccessfulTxStatus(0), createSuccessfulTxStatus(-60000)]);
+        txStatsCollector.getTotalFinishedTx().should.equal(3);
+    });
+
+    it('should record the transaction statistics if the status was created after the round started', () => {
+        txStatsCollector.txSubmitted(1);
+        txStatsCollector.getTotalSuccessfulTx().should.equal(0);
+        txStatsCollector.txFinished(createSuccessfulTxStatus(60000));
+        txStatsCollector.getTotalSuccessfulTx().should.equal(1);
+    });
+
+    it('should record the transaction statistics if the status was created at the same time the round started', () => {
+        txStatsCollector.txSubmitted(1);
+        txStatsCollector.getTotalSuccessfulTx().should.equal(0);
+        txStatsCollector.txFinished(createSuccessfulTxStatus(0));
+        txStatsCollector.getTotalSuccessfulTx().should.equal(1);
+    });
+
+    it('should NOT record the transaction statistics if the status was created before the round started', () => {
+        txStatsCollector.txSubmitted(1);
+        txStatsCollector.getTotalSuccessfulTx().should.equal(0);
+        txStatsCollector.txFinished(createSuccessfulTxStatus(-60000));
+        txStatsCollector.getTotalSuccessfulTx().should.equal(0);
+    });
+
+    it('should include only the status results that were created on of after the round started', () => {
+        txStatsCollector.txSubmitted(3);
+        txStatsCollector.txFinished([createSuccessfulTxStatus(60000), createSuccessfulTxStatus(0), createSuccessfulTxStatus(-60000)]);
+        txStatsCollector.getTotalSuccessfulTx().should.equal(2);
+    });
+});
diff --git a/packages/caliper-core/test/core/transaction-status.js b/packages/caliper-core/test/core/transaction-status.js
@@ -0,0 +1,36 @@
+/*
+* Licensed under the Apache License, Version 2.0 (the "License");
+* you may not use this file except in compliance with the License.
+* You may obtain a copy of the License at
+*
+* http://www.apache.org/licenses/LICENSE-2.0
+*
+* Unless required by applicable law or agreed to in writing, software
+* distributed under the License is distributed on an "AS IS" BASIS,
+* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+* See the License for the specific language governing permissions and
+* limitations under the License.
+*/
+
+'use strict';
+
+const chai = require('chai');
+chai.should();
+
+const TxStatus = require('../../lib/common/core/transaction-status');
+
+describe('the transaction status', () => {
+    it('should create a default time creation', () => {
+        const txStatus = new TxStatus();
+        txStatus.GetTimeCreate().should.be.greaterThan(0);
+    });
+
+    it('should allow changing of the default time creation', () => {
+        const txStatus = new TxStatus();
+        const orgTimeCreate = txStatus.GetTimeCreate();
+        const newTimeCreate = Date.now() + 60000;
+        txStatus.SetTimeCreate(newTimeCreate);
+        txStatus.GetTimeCreate().should.not.equal(orgTimeCreate);
+        txStatus.GetTimeCreate().should.equal(newTimeCreate);
+    });
+});
diff --git a/packages/caliper-fabric/lib/connector-versions/peer-gateway/PeerGateway.js b/packages/caliper-fabric/lib/connector-versions/peer-gateway/PeerGateway.js
@@ -304,10 +304,10 @@ class PeerGateway extends ConnectorBase {
         // set transaction invocation result to return
         try {
             const proposal = smartContract.newProposal(invokeSettings.contractFunction, proposalOptions);
-            invokeStatus.Set('time_create', Date.now());
             invokeStatus.SetID(proposal.getTransactionId());
             if (isSubmit) {
                 invokeStatus.Set('request_type', 'transaction');
+                invokeStatus.SetTimeCreate(Date.now());
                 const transaction = await proposal.endorse();
                 const subtx = await transaction.submit();
                 const status = await subtx.getStatus();
@@ -320,6 +320,7 @@ class PeerGateway extends ConnectorBase {
                 invokeStatus.SetResult(subtx.getResult());
             } else {
                 invokeStatus.Set('request_type', 'query');
+                invokeStatus.SetTimeCreate(Date.now());
                 invokeStatus.SetResult(await proposal.evaluate());
                 invokeStatus.SetStatusSuccess();
             }

diff --git a/packages/caliper-fabric/lib/connector-versions/v1/FabricGateway.js b/packages/caliper-fabric/lib/connector-versions/v1/FabricGateway.js
@@ -377,7 +377,7 @@ class V1FabricGateway extends ConnectorBase {
 
             if (isSubmit) {
                 invokeStatus.Set('request_type', 'transaction');
-                invokeStatus.Set('time_create', Date.now());
+                invokeStatus.SetTimeCreate(Date.now());
                 result = await transaction.submit(...invokeSettings.contractArguments);
             } else {
 
@@ -386,7 +386,7 @@ class V1FabricGateway extends ConnectorBase {
                 }
 
                 invokeStatus.Set('request_type', 'query');
-                invokeStatus.Set('time_create', Date.now());
+                invokeStatus.SetTimeCreate(Date.now());
                 result = await transaction.evaluate(...invokeSettings.contractArguments);
             }
 

diff --git a/packages/caliper-fabric/lib/connector-versions/v1/FabricNonGateway.js b/packages/caliper-fabric/lib/connector-versions/v1/FabricNonGateway.js
@@ -343,8 +343,8 @@ class V1Fabric extends ConnectorBase {
                     reject(new Error('TIMEOUT'));
                 }, this._getRemainingTimeout(startTime, timeout));
 
-                invokeStatus.Set('time_create', Date.now());
                 try {
+                    invokeStatus.SetTimeCreate(Date.now());
                     const result = await channel.queryByChaincode(proposalRequest);
                     clearTimeout(timeoutHandle);
                     resolve(result);
@@ -467,7 +467,7 @@ class V1Fabric extends ConnectorBase {
         try {
             try {
                 // account for the elapsed time up to this point
-                invokeStatus.Set('time_create', Date.now());
+                invokeStatus.SetTimeCreate(Date.now());
                 proposalResponseObject = await channel.sendTransactionProposal(proposalRequest,
                     this._getRemainingTimeout(startTime, timeout));
 

diff --git a/packages/caliper-fabric/lib/connector-versions/v2/FabricGateway.js b/packages/caliper-fabric/lib/connector-versions/v2/FabricGateway.js
@@ -371,7 +371,7 @@ class V2FabricGateway extends ConnectorBase {
 
             if (isSubmit) {
                 invokeStatus.Set('request_type', 'transaction');
-                invokeStatus.Set('time_create', Date.now());
+                invokeStatus.SetTimeCreate(Date.now());
                 result = await transaction.submit(...invokeSettings.contractArguments);
             } else {
 
@@ -380,7 +380,7 @@ class V2FabricGateway extends ConnectorBase {
                 }
 
                 invokeStatus.Set('request_type', 'query');
-                invokeStatus.Set('time_create', Date.now());
+                invokeStatus.SetTimeCreate(Date.now());
                 result = await transaction.evaluate(...invokeSettings.contractArguments);
             }