Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Multi-Round Benchmark gets randomly stuck in one of the rounds #1068

Closed
3 tasks
nimaafraz opened this issue Oct 31, 2020 · 11 comments · Fixed by #1328 or #1342
Closed
3 tasks

Multi-Round Benchmark gets randomly stuck in one of the rounds #1068

nimaafraz opened this issue Oct 31, 2020 · 11 comments · Fixed by #1328 or #1342
Assignees
Labels
bug Something isn't working component/fabric Related to the HL Fabric adapter
Milestone

Comments

@nimaafraz
Copy link

nimaafraz commented Oct 31, 2020

I'm running a Multi-Round benchmark (simple benchmark) with various TPS rates. The benchmarks get randomly stuck with one unfinished transaction and never returns.

Context

I checked the container logs, everything looks normal in Peers/Orderers/CAs. The chaincode containers logs are frozen with no log after the first instance of caliper repeating the Submitted: 20 Succ: 19 Fail:0 Unfinished:1

Expected Behavior

For the benchmark, rounds execute one after another.

Actual Behavior

2020.10.30-16:33:49.628 info  [caliper] [round-orchestrator] 	Waiting 5 seconds for the next round...
2020.10.30-16:33:54.630 info  [caliper] [round-orchestrator] 	Started round 2 (open)
2020.10.30-16:33:54.632 info  [caliper] [worker-message-handler] 	Preparing Worker#0 for Round#1
2020.10.30-16:33:54.632 info  [caliper] [worker-message-handler] 	Preparing Worker#1 for Round#1
2020.10.30-16:33:54.633 info  [caliper] [worker-message-handler] 	Preparing Worker#2 for Round#1
2020.10.30-16:33:54.634 info  [caliper] [worker-message-handler] 	Preparing Worker#3 for Round#1
2020.10.30-16:33:54.635 info  [caliper] [worker-message-handler] 	Preparing Worker#4 for Round#1
2020.10.30-16:33:54.781 info  [caliper] [caliper-worker] 	Info: worker 0 prepare test phase for round 1 is starting...
2020.10.30-16:33:54.783 info  [caliper] [caliper-worker] 	Info: worker 3 prepare test phase for round 1 is starting...
2020.10.30-16:33:54.784 info  [caliper] [caliper-worker] 	Info: worker 0 prepare test phase for round 1 is completed
2020.10.30-16:33:54.784 info  [caliper] [worker-message-handler] 	Worker#0 prepared for Round#1
2020.10.30-16:33:54.786 info  [caliper] [caliper-worker] 	Info: worker 3 prepare test phase for round 1 is completed
2020.10.30-16:33:54.786 info  [caliper] [worker-message-handler] 	Worker#3 prepared for Round#1
2020.10.30-16:33:54.788 info  [caliper] [caliper-worker] 	Info: worker 4 prepare test phase for round 1 is starting...
2020.10.30-16:33:54.791 info  [caliper] [caliper-worker] 	Info: worker 4 prepare test phase for round 1 is completed
2020.10.30-16:33:54.792 info  [caliper] [worker-message-handler] 	Worker#4 prepared for Round#1
2020.10.30-16:33:54.799 info  [caliper] [caliper-worker] 	Info: worker 2 prepare test phase for round 1 is starting...
2020.10.30-16:33:54.801 info  [caliper] [caliper-worker] 	Info: worker 1 prepare test phase for round 1 is starting...
2020.10.30-16:33:54.802 info  [caliper] [caliper-worker] 	Info: worker 2 prepare test phase for round 1 is completed
2020.10.30-16:33:54.802 info  [caliper] [worker-message-handler] 	Worker#2 prepared for Round#1
2020.10.30-16:33:54.803 info  [caliper] [caliper-worker] 	Info: worker 1 prepare test phase for round 1 is completed
2020.10.30-16:33:54.803 info  [caliper] [worker-message-handler] 	Worker#1 prepared for Round#1
2020.10.30-16:33:54.804 info  [caliper] [worker-orchestrator] 	5 workers prepared, progressing to test phase.
2020.10.30-16:33:54.804 info  [caliper] [round-orchestrator] 	Monitors successfully started
2020.10.30-16:33:54.805 info  [caliper] [worker-message-handler] 	Worker#0 is starting Round#1
2020.10.30-16:33:54.806 info  [caliper] [worker-message-handler] 	Worker#3 is starting Round#1
2020.10.30-16:33:54.806 info  [caliper] [caliper-worker] 	Worker #0 starting workload loop
2020.10.30-16:33:54.807 info  [caliper] [caliper-worker] 	Worker #3 starting workload loop
2020.10.30-16:33:54.807 info  [caliper] [worker-message-handler] 	Worker#2 is starting Round#1
2020.10.30-16:33:54.807 info  [caliper] [worker-message-handler] 	Worker#1 is starting Round#1
2020.10.30-16:33:54.808 info  [caliper] [caliper-worker] 	Worker #2 starting workload loop
2020.10.30-16:33:54.808 info  [caliper] [worker-message-handler] 	Worker#4 is starting Round#1
2020.10.30-16:33:54.809 info  [caliper] [caliper-worker] 	Worker #4 starting workload loop
2020.10.30-16:33:54.809 info  [caliper] [caliper-worker] 	Worker #1 starting workload loop
2020.10.30-16:33:59.807 info  [caliper] [default-observer] 	[open Round 1 Transaction Info] - Submitted: 41 Succ: 34 Fail:0 Unfinished:7
2020.10.30-16:34:04.807 info  [caliper] [default-observer] 	[open Round 1 Transaction Info] - Submitted: 98 Succ: 93 Fail:0 Unfinished:5
2020.10.30-16:34:05.518 info  [caliper] [worker-message-handler] 	Worker#3 finished Round#1
2020.10.30-16:34:05.518 info  [caliper] [worker-message-handler] 	Worker#2 finished Round#1
2020.10.30-16:34:05.519 info  [caliper] [worker-message-handler] 	Worker#1 finished Round#1
2020.10.30-16:34:05.922 info  [caliper] [worker-message-handler] 	Worker#0 finished Round#1
2020.10.30-16:34:09.808 info  [caliper] [default-observer] 	Resetting txCount indicator count
2020.10.30-16:34:14.810 info  [caliper] [default-observer] 	[open Round 1 Transaction Info] - Submitted: 20 Succ: 19 Fail:0 Unfinished:1
2020.10.30-16:34:19.811 info  [caliper] [default-observer] 	[open Round 1 Transaction Info] - Submitted: 20 Succ: 19 Fail:0 Unfinished:1
2020.10.30-16:34:24.812 info  [caliper] [default-observer] 	[open Round 1 Transaction Info] - Submitted: 20 Succ: 19 Fail:0 Unfinished:1
2020.10.30-16:34:29.813 info  [caliper] [default-observer] 	[open Round 1 Transaction Info] - Submitted: 20 Succ: 19 Fail:0 Unfinished:1
2020.10.30-16:34:34.814 info  [caliper] [default-observer] 	[open Round 1 Transaction Info] - Submitted: 20 Succ: 19 Fail:0 Unfinished:1
2020.10.30-16:34:39.815 info  [caliper] [default-observer] 	[open Round 1 Transaction Info] - Submitted: 20 Succ: 19 Fail:0 Unfinished:1
2020.10.30-16:34:44.816 info  [caliper] [default-observer] 	[open Round 1 Transaction Info] - Submitted: 20 Succ: 19 Fail:0 Unfinished:1
2020.10.30-16:34:49.817 info  [caliper] [default-observer] 	[open Round 1 Transaction Info] - Submitted: 20 Succ: 19 Fail:0 Unfinished:1
2020.10.30-16:34:54.818 info  [caliper] [default-observer] 	[open Round 1 Transaction Info] - Submitted: 20 Succ: 19 Fail:0 Unfinished:1
2020.10.30-16:34:59.819 info  [caliper] [default-observer] 	[open Round 1 Transaction Info] - Submitted: 20 Succ: 19 Fail:0 Unfinished:1
2020.10.30-16:35:04.820 info  [caliper] [default-observer] 	[open Round 1 Transaction Info] - Submitted: 20 Succ: 19 Fail:0 Unfinished:1
2020.10.30-16:35:09.821 info  [caliper] [default-observer] 	[open Round 1 Transaction Info] - Submitted: 20 Succ: 19 Fail:0 Unfinished:1
2020.10.30-16:35:14.822 info  [caliper] [default-observer] 	[open Round 1 Transaction Info] - Submitted: 20 Succ: 19 Fail:0 Unfinished:1
2020.10.30-16:35:19.823 info  [caliper] [default-observer] 	[open Round 1 Transaction Info] - Submitted: 20 Succ: 19 Fail:0 Unfinished:1
2020.10.30-16:35:24.825 info  [caliper] [default-observer] 	[open Round 1 Transaction Info] - Submitted: 20 Succ: 19 Fail:0 Unfinished:1

Here is the Peer Logs

2020-10-31 09:13:30.575 UTC [fsblkstorage] waitForBlock -> DEBU 65dc7 Came out of wait. maxAvailaBlockNumber=[101]
2020-10-31 09:13:30.575 UTC [fsblkstorage] waitForBlock -> DEBU 65dc8 Going to wait for newer blocks. maxAvailaBlockNumber=[101], waitForBlockNum=[102]
2020-10-31 09:13:30.575 UTC [grpc] infof -> DEBU 65dc9 transport: loopyWriter.run returning. connection error: desc = "transport is closing"
2020-10-31 09:13:30.576 UTC [common.deliver] deliverBlocks -> DEBU 65dca Context canceled, aborting wait for next block
2020-10-31 09:13:30.576 UTC [common.deliverevents] func1 -> DEBU 65dcb Closing Deliver stream
2020-10-31 09:13:30.576 UTC [comm.grpc.server] 1 -> INFO 65dcd streaming call completed grpc.service=protos.Deliver grpc.method=DeliverFiltered grpc.peer_address=10.0.0.2:33432 error="context finished before block retrieved: context canceled" grpc.code=Unknown grpc.call_duration=11.281267353s
2020-10-31 09:13:30.576 UTC [fsblkstorage] waitForBlock -> DEBU 65dcc Came out of wait. maxAvailaBlockNumber=[101]
2020-10-31 09:13:30.576 UTC [fsblkstorage] waitForBlock -> DEBU 65dce Going to wait for newer blocks. maxAvailaBlockNumber=[101], waitForBlockNum=[102]
2020-10-31 09:13:30.576 UTC [fsblkstorage] waitForBlock -> DEBU 65dcf Came out of wait. maxAvailaBlockNumber=[101]
2020-10-31 09:13:30.576 UTC [grpc] infof -> DEBU 65dd0 transport: loopyWriter.run returning. connection error: desc = "transport is closing"
2020-10-31 09:13:30.576 UTC [grpc] infof -> DEBU 65dd1 transport: loopyWriter.run returning. connection error: desc = "transport is closing"
2020-10-31 09:13:30.578 UTC [grpc] infof -> DEBU 65dd2 transport: loopyWriter.run returning. connection error: desc = "transport is closing"
2020-10-31 09:13:31.811 UTC [msp] GetDefaultSigningIdentity -> DEBU 65dd3 Obtaining default signing identity
2020-10-31 09:13:31.811 UTC [msp.identity] Sign -> DEBU 65dd4 Sign: plaintext: 18012A500A3F0A1B70656572302E6F72...01120D08C0B59A80BF92C2A116108301
2020-10-31 09:13:31.811 UTC [msp.identity] Sign -> DEBU 65dd5 Sign: digest: E60808DC55EE8FB384F04B0D46F8F23D58EF9A8AA4A33436C5A732174FAE2D8A

Possible Fix

Steps to Reproduce

  1. Run Simple benchmark on a distributed 5-org scenario.

Existing issues

Context

Your Environment

  • Version used: Caliper v.0.4.1
  • Environment name and version (e.g. Chrome 39, node.js 5.4): Node 10
  • Operating System and version (desktop or mobile): UBUNTU
  • Link to your project:
@aklenik
Copy link
Contributor

aklenik commented Nov 2, 2020

@nimaafraz Look like Worker#4 didn't finish the round for some reason. Did you see any error logs on the worker side? Could you enable debug logs so we can see what happens exactly?

@aklenik aklenik added the question Further information is requested label Nov 2, 2020
@nimaafraz
Copy link
Author

@aklenik The problem is resolved when dedicating more CPU. Is there a way to see the individual worker logs? How can I enable the debug logs?

@stale
Copy link

stale bot commented Dec 25, 2020

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

@stale stale bot added the wontfix This will not be worked on label Dec 25, 2020
@ih8d8
Copy link

ih8d8 commented Jan 24, 2021

I'm facing the same problem, especially when the network is under heavy load. Like the OP, I'm testing the simple benchmark. I have reached a fairly high TPS when using caliper npm package [v0.4.0] a couple of months ago. Recently I've decided to test caliper docker image [v0.4.2] in a Kubernetes environment. I've tested both the local and the distributed [MQTT] methods. When I increase the load, there is a high probability that the test will get stuck.
This is the output I got from one of my tests:

2021.01.24-16:37:46.769 info  [caliper] [default-observer]      [open Round 0 Transaction Info] - Submitted: 780 Succ: 69 Fail:7 Unfinished:704
2021.01.24-16:37:51.759 info  [caliper] [default-observer]      [open Round 0 Transaction Info] - Submitted: 1918 Succ: 261 Fail:21 Unfinished:1636
2021.01.24-16:37:56.757 info  [caliper] [default-observer]      [open Round 0 Transaction Info] - Submitted: 3044 Succ: 325 Fail:62 Unfinished:2657
2021.01.24-16:38:01.760 info  [caliper] [default-observer]      [open Round 0 Transaction Info] - Submitted: 4325 Succ: 394 Fail:112 Unfinished:3819
2021.01.24-16:38:06.759 info  [caliper] [default-observer]      [open Round 0 Transaction Info] - Submitted: 5469 Succ: 438 Fail:170 Unfinished:4861
2021.01.24-16:38:11.770 info  [caliper] [default-observer]      [open Round 0 Transaction Info] - Submitted: 6686 Succ: 591 Fail:207 Unfinished:5888
2021.01.24-16:38:16.771 info  [caliper] [default-observer]      [open Round 0 Transaction Info] - Submitted: 7915 Succ: 680 Fail:255 Unfinished:6980
2021.01.24-16:38:21.772 info  [caliper] [default-observer]      [open Round 0 Transaction Info] - Submitted: 9216 Succ: 692 Fail:290 Unfinished:8234
2021.01.24-16:38:26.782 info  [caliper] [default-observer]      [open Round 0 Transaction Info] - Submitted: 10489 Succ: 830 Fail:353 Unfinished:9306
2021.01.24-16:38:31.780 info  [caliper] [default-observer]      [open Round 0 Transaction Info] - Submitted: 11814 Succ: 854 Fail:409 Unfinished:10551
2021.01.24-16:38:36.778 info  [caliper] [default-observer]      [open Round 0 Transaction Info] - Submitted: 13190 Succ: 891 Fail:445 Unfinished:11854
2021.01.24-16:38:41.780 info  [caliper] [default-observer]      [open Round 0 Transaction Info] - Submitted: 14427 Succ: 891 Fail:451 Unfinished:13085
2021.01.24-16:38:46.781 info  [caliper] [default-observer]      [open Round 0 Transaction Info] - Submitted: 15562 Succ: 891 Fail:491 Unfinished:14180
2021.01.24-16:38:51.781 info  [caliper] [default-observer]      [open Round 0 Transaction Info] - Submitted: 16879 Succ: 972 Fail:567 Unfinished:15340
2021.01.24-16:38:56.782 info  [caliper] [default-observer]      [open Round 0 Transaction Info] - Submitted: 18205 Succ: 989 Fail:591 Unfinished:16625
2021.01.24-16:39:01.783 info  [caliper] [default-observer]      [open Round 0 Transaction Info] - Submitted: 18691 Succ: 989 Fail:662 Unfinished:17040
2021.01.24-16:39:06.787 info  [caliper] [default-observer]      [open Round 0 Transaction Info] - Submitted: 19147 Succ: 1248 Fail:707 Unfinished:17192
2021.01.24-16:39:11.787 info  [caliper] [default-observer]      [open Round 0 Transaction Info] - Submitted: 19604 Succ: 1533 Fail:707 Unfinished:17364
2021.01.24-16:39:16.789 info  [caliper] [default-observer]      [open Round 0 Transaction Info] - Submitted: 19884 Succ: 2236 Fail:707 Unfinished:16941
2021.01.24-16:39:21.791 info  [caliper] [default-observer]      [open Round 0 Transaction Info] - Submitted: 20000 Succ: 2236 Fail:707 Unfinished:17057
2021.01.24-16:39:26.790 info  [caliper] [default-observer]      [open Round 0 Transaction Info] - Submitted: 20000 Succ: 2236 Fail:707 Unfinished:17057
2021.01.24-16:39:31.790 info  [caliper] [default-observer]      [open Round 0 Transaction Info] - Submitted: 20000 Succ: 2236 Fail:707 Unfinished:17057
2021.01.24-16:39:36.793 info  [caliper] [default-observer]      [open Round 0 Transaction Info] - Submitted: 20000 Succ: 2236 Fail:707 Unfinished:17057
2021.01.24-16:39:41.793 info  [caliper] [default-observer]      [open Round 0 Transaction Info] - Submitted: 20000 Succ: 2236 Fail:707 Unfinished:17057
2021.01.24-16:39:46.792 info  [caliper] [default-observer]      [open Round 0 Transaction Info] - Submitted: 20000 Succ: 2236 Fail:707 Unfinished:17057

These are the last lines of the caliper.log file [debug is enabled]:

2021.01.24-16:59:49.900 debug [caliper] [mqtt-messenger]        Messenger "mqttjs_ff842b35" published message to topic "worker/update": {"sender":"mqttjs_ff842b35","recipients":["mqttjs_c5eaa833"],"type":"txUpdate","content":{"subCollectors":[],"active":true,"stats":{"metadata":{"workerIndex":14,"roundIndex":0,"roundLabel":"open","roundStartTime":1611506261788,"roundFinishTime":0},"txCounters":{"totalSubmitted":1250,"totalFinished":167,"totalSuccessful":167,"totalFailed":0},"timestamps":{"firstCreateTime":1611506261835,"lastCreateTime":1611506274117,"firstFinishTime":1611506267057,"lastFinishTime":1611506355508},"latency":{"successful":{"min":3628,"max":84734,"total":9544306},"failed":{"min":9007199254740991,"max":0,"total":0}}},"type":"txUpdate"},"date":"2021-01-24T16:59:49.899Z"}
2021.01.24-16:59:50.110 debug [caliper] [mqtt-messenger]        Messenger "mqttjs_4e489ffd" published message to topic "worker/update": {"sender":"mqttjs_4e489ffd","recipients":["mqttjs_c5eaa833"],"type":"txUpdate","content":{"subCollectors":[],"active":true,"stats":{"metadata":{"workerIndex":7,"roundIndex":0,"roundLabel":"open","roundStartTime":1611506261785,"roundFinishTime":0},"txCounters":{"totalSubmitted":1250,"totalFinished":167,"totalSuccessful":167,"totalFailed":0},"timestamps":{"firstCreateTime":1611506261818,"lastCreateTime":1611506273734,"firstFinishTime":1611506264792,"lastFinishTime":1611506355508},"latency":{"successful":{"min":1958,"max":85306,"total":9621424},"failed":{"min":9007199254740991,"max":0,"total":0}}},"type":"txUpdate"},"date":"2021-01-24T16:59:50.110Z"}
2021.01.24-16:59:50.310 debug [caliper] [mqtt-messenger]        Messenger "mqttjs_eaab52e5" published message to topic "worker/update": {"sender":"mqttjs_eaab52e5","recipients":["mqttjs_c5eaa833"],"type":"txUpdate","content":{"subCollectors":[],"active":true,"stats":{"metadata":{"workerIndex":6,"roundIndex":0,"roundLabel":"open","roundStartTime":1611506261779,"roundFinishTime":0},"txCounters":{"totalSubmitted":1250,"totalFinished":160,"totalSuccessful":160,"totalFailed":0},"timestamps":{"firstCreateTime":1611506261824,"lastCreateTime":1611506273936,"firstFinishTime":1611506267127,"lastFinishTime":1611506355511},"latency":{"successful":{"min":3677,"max":84649,"total":8983374},"failed":{"min":9007199254740991,"max":0,"total":0}}},"type":"txUpdate"},"date":"2021-01-24T16:59:50.310Z"}
2021.01.24-16:59:50.318 debug [caliper] [mqtt-messenger]        Messenger "mqttjs_a3477ad3" published message to topic "worker/update": {"sender":"mqttjs_a3477ad3","recipients":["mqttjs_c5eaa833"],"type":"txUpdate","content":{"subCollectors":[],"active":true,"stats":{"metadata":{"workerIndex":3,"roundIndex":0,"roundLabel":"open","roundStartTime":1611506261779,"roundFinishTime":0},"txCounters":{"totalSubmitted":1250,"totalFinished":153,"totalSuccessful":153,"totalFailed":0},"timestamps":{"firstCreateTime":1611506261816,"lastCreateTime":1611506272580,"firstFinishTime":1611506264796,"lastFinishTime":1611506355514},"latency":{"successful":{"min":2046,"max":84517,"total":8328411},"failed":{"min":9007199254740991,"max":0,"total":0}}},"type":"txUpdate"},"date":"2021-01-24T16:59:50.317Z"}
2021.01.24-16:59:50.496 debug [caliper] [mqtt-messenger]        Messenger "mqttjs_3a49b562" published message to topic "worker/update": {"sender":"mqttjs_3a49b562","recipients":["mqttjs_c5eaa833"],"type":"txUpdate","content":{"subCollectors":[],"active":true,"stats":{"metadata":{"workerIndex":2,"roundIndex":0,"roundLabel":"open","roundStartTime":1611506261768,"roundFinishTime":0},"txCounters":{"totalSubmitted":1250,"totalFinished":168,"totalSuccessful":168,"totalFailed":0},"timestamps":{"firstCreateTime":1611506261803,"lastCreateTime":1611506274101,"firstFinishTime":1611506264896,"lastFinishTime":1611506355496},"latency":{"successful":{"min":2357,"max":84980,"total":9933750},"failed":{"min":9007199254740991,"max":0,"total":0}}},"type":"txUpdate"},"date":"2021-01-24T16:59:50.495Z"}

@stale stale bot removed the wontfix This will not be worked on label Jan 24, 2021
@stale
Copy link

stale bot commented Apr 13, 2021

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

@stale stale bot added the wontfix This will not be worked on label Apr 13, 2021
@yasser-mas
Copy link

yasser-mas commented May 25, 2021

I'm facing the same issue too

caliper_testing    | 2021.05.25-10:59:49.092 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 445 Succ: 10 Fail:18 Unfinished:417
caliper_testing    | 2021.05.25-10:59:54.070 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 60 Fail:18 Unfinished:422
caliper_testing    | 2021.05.25-10:59:59.071 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 96 Fail:18 Unfinished:386
caliper_testing    | 2021.05.25-11:00:04.073 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 176 Fail:18 Unfinished:306
caliper_testing    | 2021.05.25-11:00:09.075 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 239 Fail:18 Unfinished:243
caliper_testing    | 2021.05.25-11:00:14.077 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 311 Fail:18 Unfinished:171
caliper_testing    | 2021.05.25-11:00:19.079 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:00:24.080 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:00:29.082 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:00:34.084 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:00:39.085 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:00:44.086 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:00:49.088 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:00:54.089 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:00:59.093 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:01:04.094 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:01:09.095 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:01:14.096 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:01:19.097 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:01:24.098 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:01:29.099 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:01:34.100 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:01:39.101 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:01:44.102 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:01:49.103 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:01:54.104 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:01:59.105 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:02:04.106 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:02:09.108 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:02:14.109 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:02:19.110 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:02:24.112 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:02:29.113 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:02:34.114 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:02:39.116 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:02:44.119 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:02:49.120 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:02:54.122 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:02:59.124 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:03:04.126 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:03:09.127 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:03:14.129 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:03:19.132 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:03:24.133 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:03:29.133 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:03:34.134 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:03:39.136 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:03:44.137 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:03:49.138 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:03:54.139 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:03:59.141 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:04:04.142 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:04:09.144 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:04:14.145 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:04:19.146 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:04:24.147 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:04:29.148 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:04:34.149 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:04:39.151 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:04:44.153 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:04:49.155 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:04:54.157 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:04:59.160 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:05:04.161 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:05:09.163 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:05:14.165 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:05:19.168 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:05:24.169 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:05:29.171 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:05:34.173 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:05:39.175 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:05:44.176 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:05:49.178 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:05:54.181 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:05:59.183 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:06:04.184 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:06:09.185 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:06:14.186 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:06:19.187 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:06:24.188 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:06:29.189 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:06:34.190 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:06:39.192 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:06:44.193 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:06:49.195 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:06:54.196 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:06:59.198 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:07:04.199 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:07:09.200 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:07:14.202 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:07:19.203 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:07:24.205 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:07:29.207 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:07:34.209 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:07:39.211 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:07:44.213 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:07:49.214 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:07:54.216 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:07:59.217 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:08:04.219 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:08:09.221 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:08:14.223 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:08:19.224 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:08:24.226 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:08:29.227 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:08:34.228 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:08:39.229 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:08:44.230 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:08:49.231 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:08:54.233 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:08:59.233 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:09:04.234 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:09:09.235 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:09:14.238 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:09:19.239 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:09:24.240 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:09:29.241 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:09:34.242 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:09:39.243 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:09:44.245 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:09:49.247 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:09:54.248 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:09:59.249 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:10:04.251 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:10:09.253 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:10:14.253 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:10:19.254 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:10:24.255 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:10:29.256 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:10:34.258 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:10:39.259 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:10:44.260 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:10:49.261 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:10:54.265 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:10:59.264 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:11:04.265 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:11:09.266 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:11:14.266 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:11:19.267 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:11:24.268 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:11:29.269 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:11:34.270 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:11:39.271 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:11:44.273 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:11:49.274 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:11:54.274 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:11:59.273 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:12:04.274 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:12:09.274 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:12:14.275 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:12:19.276 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:12:24.278 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:12:29.279 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:12:34.280 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:12:39.283 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:12:44.283 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:12:49.283 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:12:54.284 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:12:59.286 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:13:04.289 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:13:09.291 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:13:14.292 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:13:19.294 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:13:24.296 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:13:29.297 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:13:34.298 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:13:39.299 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:13:44.300 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:13:49.301 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:13:54.303 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:13:59.304 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:14:04.306 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:14:09.307 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:14:14.308 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:14:19.309 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:14:24.311 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:14:29.312 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:14:34.315 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:14:39.316 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:14:44.316 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:14:49.318 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:14:54.319 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:14:59.321 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:15:04.321 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:15:09.321 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:15:14.323 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:15:19.323 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:15:24.324 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:15:29.326 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:15:34.327 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:15:39.328 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:15:44.329 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:15:49.330 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:15:54.332 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:15:59.334 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:16:04.335 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:16:09.336 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:16:14.338 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:16:19.338 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:16:24.339 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:16:29.341 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:16:34.342 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:16:39.344 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:16:44.345 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:16:49.347 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:16:54.349 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:16:59.350 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:17:04.350 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:17:09.350 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:17:14.351 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:17:19.352 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:17:24.353 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:17:29.353 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:17:34.354 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:17:39.355 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
caliper_testing    | 2021.05.25-11:17:44.356 info  [caliper] [default-observer] 	[Load Test Round 0 Transaction Info] - Submitted: 500 Succ: 358 Fail:18 Unfinished:124
^CGracefully stopping... (press Ctrl+C again to force)

@stale stale bot removed the wontfix This will not be worked on label May 25, 2021
@davidkel
Copy link
Contributor

davidkel commented Feb 4, 2022

My guess here is that everyone is using hyperledger fabric. This is probably a combination of 2 things

  1. The default timeouts in caliper for fabric are specified in milliseconds but passed into the fabric sdk which expects seconds therefore the reason a worker doesn't complete is it's waiting a very long time for a transaction to complete (which will never complete probably due to point 2) so it appears to hang see can't catch the error of commitTimeOut , because of the unit is not uniform #1141
  2. Under load it's likely either the node-sdk is missing events or the request to commit the transaction is lost by fabric (fabric doesn't guarantee that a transaction sent to an orderer will be committed. Things were improved in 2.4 so that you are told if at least it was successfully received by the lead orderer in a raft configuration but it's still no guarantee). However as I have been running with fabric 2.4 and a single raft orderer it's more likely that the fabric node-sdk is missing events under load.

You can change the timeout by adding the following to the command line when you launch caliper

--caliper-fabric-timeout-invokeorquery 60

which will change the timeout to 60 seconds

The problem still remains regarding whether the transaction was committed or whether the node-sdk missed the event

@davidkel davidkel added bug Something isn't working component/fabric Related to the HL Fabric adapter good first issue Good for newcomers and removed question Further information is requested labels Feb 4, 2022
@davidkel
Copy link
Contributor

Even with a timeout change a build failed with the same problem. This was using fabric sdk 2.1 which may have contributed to the hang as this version is not supported, it's possible that timeouts are not handled properly. Really need to get rid of all the unsupported stuff that is still within caliper.

@davidkel davidkel removed the good first issue Good for newcomers label Mar 2, 2022
@CaixiangFan
Copy link

I am facing the same issue when benchmarking Besu using Caliper 0.4.2 with simple benchmark.

caliper | 2022.03.22-04:41:24.271 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:41:29.273 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:41:34.273 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:41:39.274 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:41:44.275 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:41:49.275 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:41:54.276 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:41:59.276 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:42:04.275 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:42:09.276 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:42:14.277 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:42:19.277 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:42:24.277 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:42:29.277 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:42:34.277 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:42:39.277 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:42:44.278 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:42:49.279 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:42:54.279 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:42:59.280 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:43:04.280 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:43:09.282 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:43:14.283 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:43:19.283 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:43:24.284 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:43:29.287 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:43:34.287 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:43:39.287 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:43:44.288 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:43:49.289 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:43:54.290 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:43:59.290 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:44:04.290 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:44:09.291 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:44:14.292 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:44:19.292 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:44:24.294 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:44:29.295 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:44:34.295 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:44:39.296 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:44:44.296 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:44:49.297 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:44:54.298 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:44:59.297 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:45:04.299 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:45:09.300 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:45:14.300 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:45:19.300 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:45:24.301 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:45:29.301 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:45:34.301 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:45:39.303 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:45:44.304 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:45:49.304 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:45:54.304 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:45:59.305 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:46:04.306 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:46:09.307 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3
caliper | 2022.03.22-04:46:14.307 info [caliper] [default-observer] [query Round 1 Transaction Info] - Submitted: 600 Succ: 597 Fail:0 Unfinished:3

@davidkel
Copy link
Contributor

I believe I have tracked down now why this can happen it's related to timing and not handling errors of a submitted transaction and marking it complete. For example there are situations in the fabric connector that can throw an error before a transaction is submitted and thus the connector doesn't try to handle these errors as it itself throws it. Caliper itself should have generic handling when a submit transaction fails

@davidkel davidkel added this to the v0.5.0 milestone Apr 26, 2022
@davidkel davidkel self-assigned this Apr 26, 2022
davidkel added a commit to davidkel/caliper that referenced this issue May 4, 2022
A Scenario was discovered where if you send a single txn and the
connector throws an error then that single txn never finishes and the
worker loops forever waiting for that transaction to finish.

eg in the workload

```
invokerIdentity: 'unknownuser'
```

example benchmark
```
test:
  name: fixed-asset-test
  description: >-
    This is a test yaml for the existing fixed-asset benchmarks
  workers:
    type: local
    number: 1
  rounds:
    - label: empty-contract-evaluate
      chaincodeID: fixed-asset
      txNumber: 1
      rateControl:
        type: fixed-rate
        opts:
          tps: 2
      workload:
        module: benchmarks/api/fabric/workloads/empty-contract.js
        arguments:
          chaincodeID: fixed-asset
          consensus: false
```

In the wider support for connectors though the caliper framework should
ensure that connectors that either don't handle errors or throw errors
should make sure that the submission is registered as a failure (which
is what a connector would do if it did catch an error)

This fix ensures that any error received will mark a transaction as
finished

closes hyperledger#1068

Signed-off-by: D <d_kelsey@uk.ibm.com>
davidkel added a commit that referenced this issue May 9, 2022
A Scenario was discovered where if you send a single txn and the
connector throws an error then that single txn never finishes and the
worker loops forever waiting for that transaction to finish.

eg in the workload

```
invokerIdentity: 'unknownuser'
```

example benchmark
```
test:
  name: fixed-asset-test
  description: >-
    This is a test yaml for the existing fixed-asset benchmarks
  workers:
    type: local
    number: 1
  rounds:
    - label: empty-contract-evaluate
      chaincodeID: fixed-asset
      txNumber: 1
      rateControl:
        type: fixed-rate
        opts:
          tps: 2
      workload:
        module: benchmarks/api/fabric/workloads/empty-contract.js
        arguments:
          chaincodeID: fixed-asset
          consensus: false
```

In the wider support for connectors though the caliper framework should
ensure that connectors that either don't handle errors or throw errors
should make sure that the submission is registered as a failure (which
is what a connector would do if it did catch an error)

This fix ensures that any error received will mark a transaction as
finished

closes #1068

Signed-off-by: D <d_kelsey@uk.ibm.com>
@davidkel
Copy link
Contributor

nope not tracked this down after all as it is happening with the new fabric 2.4 connector. It doesn't appear to be related to fabric connectors. see #1340

@davidkel davidkel reopened this May 13, 2022
davidkel added a commit to davidkel/caliper that referenced this issue May 17, 2022
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 hyperledger#1068
closes hyperledger#1340

Signed-off-by: D <d_kelsey@uk.ibm.com>
davidkel added a commit that referenced this issue May 17, 2022
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 <d_kelsey@uk.ibm.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working component/fabric Related to the HL Fabric adapter
Projects
None yet
6 participants