Handling tx send failures (#388)

* Handling failed sent transactions

* Use actual sent

* More txs_sent

* Correct num data points

src/python/ten/test/basetest.py

@@ -504,3 +504,12 @@ def ratio_failures(self, file, threshold=0.05):
         self.log.info('Ratio of failures is %.2f' % ratio)
         if ratio > threshold: self.addOutcome(FAILED, outcomeReason='Failure ratio > 0.05', abortOnError=False)
         return ratio
+
+    def txs_sent(self, file):
+        """Search through a log for number of transactions sent. """
+        regex = re.compile('Number of transactions sent = (?P<sent>.*)$', re.M)
+        with open(file, 'r') as fp:
+            for line in fp.readlines():
+                result = regex.search(line)
+                if result is not None: return int(result.group('sent'))
+        return 0

tests/ten/ten_per_001/run.py

@@ -8,7 +8,7 @@
 
 
 class PySysTest(TenNetworkTest):
-    ITERATIONS = 5000       # number of iterations per client
+    ITERATIONS = 2048       # number of iterations per client
 
     def __init__(self, descriptor, outsubdir, runner):
         super().__init__(descriptor, outsubdir, runner)

tests/ten/ten_per_002/Input/client.py

@@ -31,16 +31,14 @@ def run(name, chainId, web3, account, num_accounts, num_iterations, amount, gas_
 
     logging.info('Bulk sending transactions to the network')
     receipts = []
-    stats = [0,0]
     for tx in txs:
         try:
             receipts.append((web3.eth.send_raw_transaction(tx[0].rawTransaction), tx[1]))
-            stats[0] += 1
-        except:
-            logging.error('Error sending raw transaction, sent = %d', len(receipts))
-            stats[1] += 1
-
-    logging.warning('Ratio failures = %.2f', float(stats[1]) / sum(stats))
+        except Exception as e:
+            logging.error('Error sending raw transaction', e)
+            logging.warning('Continuing with smaller number of transactions ...')
+            break
+    logging.info('Number of transactions sent = %d', len(receipts))
 
     logging.info('Waiting for last transaction')
     web3.eth.wait_for_transaction_receipt(receipts[-1][0], timeout=600)

tests/ten/ten_per_002/run.py

@@ -33,9 +33,12 @@ def execute(self):
         pk2, conn2 = self.setup_client('client_two', funds_needed)
         self.run_client('client_one', pk1, conn1)
         self.run_client('client_two', pk2, conn2)
+        txs_sent = 0
         for i in self.clients:
-            self.waitForGrep(file='client_%s.out' % i, expr='Client client_%s completed' % i, timeout=900)
-            self.ratio_failures(file=os.path.join(self.output, 'client_%s.out' % i))
+            stdout = os.path.join(self.output,'client_%s.out' % i)
+            self.waitForGrep(file=stdout, expr='Client client_%s completed' % i, timeout=900)
+            self.assertGrep(file=stdout, expr='Error sending raw transaction', contains=False, abortOnError=False)
+            txs_sent += self.txs_sent(file=stdout)
 
         # process and graph the output
         data = [self.load_data('client_%s.log' % i) for i in self.clients]
@@ -53,11 +56,11 @@ def execute(self):
 
         branch = GnuplotHelper.buildInfo().branch
         duration = last - first
-        average = float(len(self.clients)*self.ITERATIONS) / float(duration) if duration != 0 else 0
+        average = float(txs_sent) / float(duration) if duration != 0 else 0
         date = datetime.now().strftime("%Y/%m/%d %H:%M:%S")
         GnuplotHelper.graph(self, os.path.join(self.input, 'gnuplot.in'),
                             branch, date,
-                            str(self.mode), str(len(self.clients)*self.ITERATIONS), str(duration), '%.3f' % average)
+                            str(self.mode), str(txs_sent), str(duration), '%.3f' % average)
 
         # persist the result
         self.results_db.insert_result(self.descriptor.id, self.mode, int(time.time()), average)
@@ -104,4 +107,3 @@ def bin_data(self, first, last, data, binned_data):
         for _, t in data: b[t] = 1 if t not in b else b[t] + 1
         for t in range(first, last+1): binned_data[t-first] = 0 if t not in b else b[t]
         return binned_data
-

tests/ten/ten_per_003/Input/client.py

@@ -39,17 +39,16 @@ def run(name, chainId, web3, sending_accounts, num_accounts, num_iterations, amo
         txs.append((tx, i))
 
     logging.info('Bulk sending transactions to the network')
-    stats = [0,0]
     receipts = []
     start_time = time.perf_counter()
     for tx in txs:
         try:
             receipts.append((web3.eth.send_raw_transaction(tx[0].rawTransaction), tx[1]))
-            stats[0] += 1
-        except:
-            logging.error('Error sending raw transaction, sent = %d', len(receipts))
-            stats[1] += 1
-    logging.warning('Ratio failures = %.2f', float(stats[1]) / sum(stats))
+        except Exception as e:
+            logging.error('Error sending raw transaction', e)
+            logging.warning('Continuing with smaller number of transactions ...')
+            break
+    logging.info('Number of transactions sent = %d', len(receipts))
 
     end_time = time.perf_counter()
     duration = end_time - start_time

tests/ten/ten_per_003/run.py

@@ -34,9 +34,12 @@ def execute(self):
         pk_file2, conn2 = self.setup_client('client_two', funds_needed)
         self.run_client('client_one', pk_file1, conn1)
         self.run_client('client_two', pk_file2, conn2)
+        txs_sent = 0
         for i in self.clients:
-            self.waitForGrep(file='client_%s.out' % i, expr='Client client_%s completed' % i, timeout=900)
-            self.ratio_failures(file=os.path.join(self.output, 'client_%s.out' % i))
+            stdout = os.path.join(self.output,'client_%s.out' % i)
+            self.waitForGrep(file=stdout, expr='Client client_%s completed' % i, timeout=900)
+            self.assertGrep(file=stdout, expr='Error sending raw transaction', contains=False, abortOnError=False)
+            txs_sent += self.txs_sent(file=stdout)
 
         # process and graph the output
         data = [self.load_data('client_%s.log' % i) for i in self.clients]
@@ -54,11 +57,11 @@ def execute(self):
 
         branch = GnuplotHelper.buildInfo().branch
         duration = last - first
-        average = float(len(self.clients) * self.ITERATIONS) / float(duration) if duration != 0 else 0
+        average = float(txs_sent) / float(duration) if duration != 0 else 0
         date = datetime.now().strftime("%Y/%m/%d %H:%M:%S")
         GnuplotHelper.graph(self, os.path.join(self.input, 'gnuplot.in'),
                             branch, date,
-                            str(self.mode), str(len(self.clients) * self.ITERATIONS), str(duration), '%.3f' % average)
+                            str(self.mode), str(txs_sent), str(duration), '%.3f' % average)
 
         # persist the result
         self.results_db.insert_result(self.descriptor.id, self.mode, int(time.time()), average)

tests/ten/ten_per_004/Input/client.py

@@ -30,16 +30,15 @@ def run(name, chainId, web3, account, num_accounts, num_iterations, amount, gas_
         txs.append((tx, i))
 
     logging.info('Bulk sending transactions to the network')
-    stats = [0,0]
     receipts = []
     for tx in txs:
         try:
             receipts.append((web3.eth.send_raw_transaction(tx[0].rawTransaction), tx[1]))
-            stats[0] += 1
-        except:
-            logging.error('Error sending raw transaction, sent = %d', len(receipts))
-            stats[1] += 1
-    logging.warning('Ratio failures = %.2f', float(stats[1]) / sum(stats))
+        except Exception as e:
+            logging.error('Error sending raw transaction', e)
+            logging.warning('Continuing with smaller number of transactions ...')
+            break
+    logging.info('Number of transactions sent = %d', len(receipts))
 
     logging.info('Waiting for last transaction')
     web3.eth.wait_for_transaction_receipt(receipts[-1][0], timeout=600)

tests/ten/ten_per_004/run.py

@@ -1,7 +1,7 @@
 import os, time
 from datetime import datetime
 from collections import OrderedDict
-from pysys.constants import PASSED, FAILED
+from pysys.constants import PASSED
 from ten.test.basetest import TenNetworkTest
 from ten.test.utils.gnuplot import GnuplotHelper
 
@@ -31,9 +31,12 @@ def execute(self):
         # run the clients
         setup = [self.setup_client('client_%d' % i, funds_needed) for i in range(self.CLIENTS)]
         for i in range(self.CLIENTS): self.run_client('client_%d' % i, setup[i][0], setup[i][1])
+        txs_sent = 0
         for i in range(self.CLIENTS):
-            self.waitForGrep(file='client_%d.out' % i, expr='Client client_%d completed' % i, timeout=900)
-            self.ratio_failures(file=os.path.join(self.output, 'client_%d.out' % i))
+            stdout = os.path.join(self.output,'client_%d.out' % i)
+            self.waitForGrep(file=stdout, expr='Client client_%d completed' % i, timeout=900)
+            self.assertGrep(file=stdout, expr='Error sending raw transaction', contains=False, abortOnError=False)
+            txs_sent += self.txs_sent(file=stdout)
 
         # process and graph the output
         data = [self.load_data('client_%d.log' % i) for i in range(self.CLIENTS)]
@@ -59,7 +62,7 @@ def execute(self):
         date = datetime.now().strftime("%Y/%m/%d %H:%M:%S")
         GnuplotHelper.graph(self, os.path.join(self.input, 'gnuplot.in'),
                             branch, date,
-                            str(self.mode), str(self.CLIENTS*self.ITERATIONS), str(duration), '%d' % self.CLIENTS)
+                            str(self.mode), str(txs_sent), str(duration), '%d' % self.CLIENTS)
 
         # persist the result
         self.results_db.insert_result(self.descriptor.id, self.mode, int(time.time()), average)

tests/ten/ten_per_005/Input/storage_client.py

@@ -41,12 +41,11 @@ def run(name, chainId, web3, account, contract, num_iterations, gas_limit):
     for tx in txs:
         try:
             receipts.append((web3.eth.send_raw_transaction(tx[0].rawTransaction), tx[1]))
-            stats[0] += 1
         except Exception as e:
-            logging.error('Error sending raw transaction, sent = %d', len(receipts))
-            logging.error('Exception is', e)
-            stats[1] += 1
-    logging.warning('Ratio failures = %.2f', float(stats[1]) / sum(stats))
+            logging.error('Error sending raw transaction', e)
+            logging.warning('Continuing with smaller number of transactions ...')
+            break
+    logging.info('Number of transactions sent = %d', len(receipts))
 
     for receipt in tenths(receipts):
         logging.info('Waiting for transaction receipt number  %s', receipt[1])

tests/ten/ten_per_005/run.py

@@ -33,9 +33,12 @@ def execute(self):
         # run the clients
         setup = [self.setup_client('client_%d' % i, funds_needed) for i in range(self.CLIENTS)]
         for i in range(self.CLIENTS): self.run_client('client_%d' % i, storage, setup[i][0], setup[i][1])
+        txs_sent = 0
         for i in range(self.CLIENTS):
-            self.waitForGrep(file='client_%d.out' % i, expr='Client client_%d completed' % i, timeout=900)
-            self.ratio_failures(file=os.path.join(self.output, 'client_%d.out' % i))
+            stdout = os.path.join(self.output,'client_%d.out' % i)
+            self.waitForGrep(file=stdout, expr='Client client_%d completed' % i, timeout=900)
+            self.assertGrep(file=stdout, expr='Error sending raw transaction', contains=False, abortOnError=False)
+            txs_sent += self.txs_sent(file=stdout)
 
         # process and graph the output
         data = [self.load_data('client_%d.log' % i) for i in range(self.CLIENTS)]
@@ -61,7 +64,7 @@ def execute(self):
         date = datetime.now().strftime("%Y/%m/%d %H:%M:%S")
         GnuplotHelper.graph(self, os.path.join(self.input, 'gnuplot.in'),
                             branch, date,
-                            str(self.mode), str(self.CLIENTS * self.ITERATIONS), str(duration), '%d' % self.CLIENTS)
+                            str(self.mode), str(txs_sent), str(duration), '%d' % self.CLIENTS)
 
         # persist the result
         self.results_db.insert_result(self.descriptor.id, self.mode, int(time.time()), average)

tests/ten/ten_per_006/Input/client.py

@@ -34,29 +34,25 @@ def run(name, chainId, web3, account, num_accounts, num_iterations, amount, gas_
 
     logging.info('Bulk sending transactions to the network')
     receipts = []
-    stats = [0,0]
     for tx in txs:
         try:
             receipt = web3.eth.send_raw_transaction(tx[0].rawTransaction)
             receipts.append((receipt, tx[1]))
             logging.info('Sent %d', tx[1])
-            stats[0] += 1
         except Exception as e:
-            logging.info('Error sending raw transaction, sent = %d', len(receipts))
-            logging.error(e)
-            stats[1] += 1
+            logging.error('Error sending raw transaction', e)
+            logging.warning('Continuing with smaller number of transactions ...')
+            break
+    logging.info('Number of transactions sent = %d', len(receipts))
 
     logging.info('Waiting for transactions')
     for receipt in receipts:
         try:
             web3.eth.wait_for_transaction_receipt(receipt[0], timeout=30)
             logging.info('Received tx receipt for %d' % receipt[1])
-            stats[0] += 1
         except Exception as e:
             logging.error('Timedout waiting for %d' % receipt[1])
             logging.error(e)
-            stats[1] += 1
-    logging.warning('Ratio failures = %.2f',  float(stats[1]) / sum(stats))
 
     logging.info('Logging the timestamps of each transaction')
     with open('%s_throughput.log' % name, 'w') as fp:

tests/ten/ten_per_006/run.py

@@ -2,7 +2,7 @@
 import numpy as np
 from datetime import datetime
 from collections import OrderedDict
-from pysys.constants import PASSED, FAILED
+from pysys.constants import PASSED
 from ten.test.basetest import TenNetworkTest
 from ten.test.utils.gnuplot import GnuplotHelper
 
@@ -36,6 +36,7 @@ def execute(self):
             scale = scale + increment
 
         # run the clients and wait for their completion
+        txs_sent = 0
         results_file = os.path.join(self.output, 'results.log')
         with open(results_file, 'w') as fp:
             for clients in [2,3,4]:
@@ -50,12 +51,13 @@ def execute(self):
                 start_ns = time.perf_counter_ns()
                 with open(signal, 'w') as sig: sig.write('go')
                 for i in range(0, clients):
-                    self.waitForGrep(file=os.path.join(out_dir, 'client_%s.out' % i),
-                                     expr='Client client_%s completed' % i, timeout=300)
-                    self.ratio_failures(file=os.path.join(out_dir, 'client_%s.out' % i))
+                    stdout = os.path.join(out_dir, 'client_%s.out' % i)
+                    self.waitForGrep(file=stdout, expr='Client client_%s completed' % i, timeout=300)
+                    self.assertGrep(file=stdout, expr='Error sending raw transaction', contains=False, abortOnError=False)
+                    txs_sent += self.txs_sent(file=stdout)
                 end_ns = time.perf_counter_ns()
 
-                bulk_throughput = float(clients * self.ITERATIONS) / float((end_ns - start_ns) / 1e9)
+                bulk_throughput = float(txs_sent) / float((end_ns - start_ns) / 1e9)
                 throughput = self.process_throughput(clients, out_dir)
                 self.log.info('Bulk rate throughput %.2f (requests/sec)' % bulk_throughput)
                 self.log.info('Approx. throughput %.2f (requests/sec)' % throughput)
@@ -152,4 +154,3 @@ def find_overlap(self, lists):
         overlap = np.array(lists[0])
         for l in lists[1:]: overlap = np.intersect1d(overlap, np.array(l))
         return overlap.tolist()[0], overlap.tolist()[-1]
-

tests/ten/ten_per_010/run.py

@@ -30,13 +30,13 @@ def execute(self):
 
                 with open(signal, 'w') as sig: sig.write('go')
                 for i in range(0, clients):
-                    self.waitForGrep(file=os.path.join(out_dir, 'client_%s.out' % i),
-                                     expr='Client client_%s completed' % i, timeout=300)
-                    self.ratio_failures(file=os.path.join(out_dir, 'client_%s.out' % i))
+                    stdout = os.path.join(out_dir, 'client_%s.out' % i)
+                    self.waitForGrep(file=stdout, expr='Client client_%s completed' % i, timeout=300)
+                    self.ratio_failures(file=stdout)
 
                 end_ns = time.perf_counter_ns()
-                bulk_throughput = float(clients * self.ITERATIONS) / float((end_ns-start_ns)/1e9)
-                avg_latency, mode_latency = self.process_latency(clients, out_dir)
+                num_data, avg_latency, mode_latency = self.process_latency(clients, out_dir)
+                bulk_throughput = float(num_data) / float((end_ns-start_ns)/1e9)
                 throughput = self.process_throughput(clients, out_dir, start_ns, end_ns)
                 self.log.info('Bulk rate throughput %.2f (requests/sec)' % bulk_throughput)
                 self.log.info('Approx. throughput %.2f (requests/sec)' % throughput)
@@ -85,7 +85,8 @@ def process_latency(self, num_clients, out_dir):
             with open(os.path.join(out_dir, 'client_%s_latency.log' % i), 'r') as fp:
                 for line in fp.readlines(): data.append(float(line.strip()))
         data.sort()
-        avg_latency = (sum(data) / len(data))
+        num_data = len(data)
+        avg_latency = (sum(data) / num_data)
 
         bins = self.bin_array(data)
         max_value = 0
@@ -97,7 +98,7 @@ def process_latency(self, num_clients, out_dir):
                     mode_latency = b
                 fp.write('%.2f %d\n' % (b, v))
             fp.flush()
-        return avg_latency, mode_latency
+        return num_data, avg_latency, mode_latency
 
     def process_throughput(self, num_clients, out_dir, start, end):
         client_bins = []       # bins for a given client

tests/ten/ten_per_011/run.py

@@ -45,16 +45,16 @@ def execute(self):
 
                 with open(signal, 'w') as sig: sig.write('go')
                 for i in range(0, clients):
-                    self.waitForGrep(file=os.path.join(out_dir, 'client_%s.out' % i),
-                                     expr='Client client_%s completed' % i, timeout=300)
-                    self.ratio_failures(file=os.path.join(out_dir, 'client_%s.out' % i))
+                    stdout = os.path.join(out_dir, 'client_%s.out' % i)
+                    self.waitForGrep(file=stdout, expr='Client client_%s completed' % i, timeout=300)
+                    self.ratio_failures(file=stdout)
 
                 # stop transacting to set the storage value
                 hprocess.stop()
 
                 end_ns = time.perf_counter_ns()
-                bulk_throughput = float(clients * self.ITERATIONS) / float((end_ns - start_ns) / 1e9)
-                avg_latency, mode_latency, nnth_percentile = self.process_latency(clients, out_dir)
+                num_data, avg_latency, mode_latency, nnth_percentile = self.process_latency(clients, out_dir)
+                bulk_throughput = float(num_data) / float((end_ns - start_ns) / 1e9)
                 throughput = self.process_throughput(clients, out_dir, start_ns, end_ns)
                 self.log.info('Bulk rate throughput %.2f (requests/sec)' % bulk_throughput)
                 self.log.info('Approx. throughput %.2f (requests/sec)' % throughput)
@@ -126,7 +126,8 @@ def process_latency(self, num_clients, out_dir):
             with open(os.path.join(out_dir, 'client_%s_latency.log' % i), 'r') as fp:
                 for line in fp.readlines(): data.append(float(line.strip()))
         data.sort()
-        avg_latency = (sum(data) / len(data))
+        num_data = len(data)
+        avg_latency = (sum(data) / num_data)
         nnth_percentile = np.percentile(data, 99)
 
         bins = self.bin_array(data)
@@ -139,7 +140,7 @@ def process_latency(self, num_clients, out_dir):
                     mode_latency = b
                 fp.write('%.2f %d\n' % (b, v))
             fp.flush()
-        return avg_latency, mode_latency, nnth_percentile
+        return num_data, avg_latency, mode_latency, nnth_percentile
 
     def process_throughput(self, num_clients, out_dir, start, end):
         client_bins = []  # bins for a given client