38: 2019-06-05 10:44:22.240 | DEBUG | infra.jsonrpc:log_response:229 - #0 {'id': 0, 'result': {'commit': 26, 'term': 2}, 'error': None, 'jsonrpc': '2.0', 'commit': 26, 'term': 2, 'global_commit': 26}
38: 2019-06-05 10:44:23.298 | INFO | infra.jsonrpc:log_request:217 - [127.89.82.26:60798] #0 getCommit {} (node 0 (user))
38: 2019-06-05 10:44:23.308 | DEBUG | infra.jsonrpc:log_response:229 - #0 {'id': 0, 'result': {'commit': 26, 'term': 2}, 'error': None, 'jsonrpc': '2.0', 'commit': 26, 'term': 2, 'global_commit': 26}
38: 2019-06-05 10:44:24.366 | INFO | infra.jsonrpc:log_request:217 - [127.89.82.26:60798] #0 getCommit {} (node 0 (user))
38: 2019-06-05 10:44:24.376 | DEBUG | infra.jsonrpc:log_response:229 - #0 {'id': 0, 'result': {'commit': 26, 'term': 2}, 'error': None, 'jsonrpc': '2.0', 'commit': 26, 'term': 2, 'global_commit': 26}
38: 2019-06-05 10:44:24.434 | INFO | infra.jsonrpc:log_request:217 - [127.89.82.26:60798] #0 getMetrics {} (node 0 (user))
38: 2019-06-05 10:44:24.496 | DEBUG | infra.jsonrpc:log_response:229 - #0 {'id': 0, 'result': {'histogram': {'buckets': {'100..103': 1, '10240..10751': 795, '10752..11263': 2, '108..111': 1, '1344..1407': 1, '1408..1471': 2, '1664..1727': 1, '1792..1855': 1, '1856..1919': 1, '1984..2047': 1, '2048..2175': 1, '2176..2303': ...
38: 2019-06-05 10:44:24.497 | INFO | infra.rates:_get_metrics:84 - Filtering histogram results...
38: 2019-06-05 10:44:29.499 | ERROR | infra.remote_client:wait:102 - Failed to wait on client client_0
38: Traceback (most recent call last):
38:
38: File "/home/ci/agent/_work/4/s/samples/apps/smallbank/tests/small_bank_client.py", line 22, in <module>
38: client.run(args.build_dir, get_command, args)
38: │ │ │ │ │ └ Namespace(accounts=10, app_script=None, build_dir='.', client='./small_bank_client', client_nodes=None, config='/home/ci/agent/_...
38: │ │ │ │ └ <function get_command at 0x7f369d254e18>
38: │ │ │ └ '.'
38: │ │ └ Namespace(accounts=10, app_script=None, build_dir='.', client='./small_bank_client', client_nodes=None, config='/home/ci/agent/_...
38: │ └ <function run at 0x7f369d254d08>
38: └ <module 'client' from '/home/ci/agent/_work/4/s/tests/client.py'>
38:
38: File "/home/ci/agent/_work/4/s/tests/client.py", line 70, in run
38: infra.runner.run(*args, **kwargs)
38: │ │ │ │ └ {}
38: │ │ │ └ ('.', <function get_command at 0x7f369d254e18>, Namespace(accounts=10, app_script=None, build_dir='.', client='./small_bank_clie...
38: │ │ └ <function run at 0x7f369d254a60>
38: │ └ <module 'infra.runner' from '/home/ci/agent/_work/4/s/tests/infra/runner.py'>
38: └ <module 'infra' from '/home/ci/agent/_work/4/s/tests/infra/__init__.py'>
38:
38: File "/home/ci/agent/_work/4/s/tests/infra/runner.py", line 130, in run
38: remote_client.wait()
38: │ └ <bound method CCFRemoteClient.wait of <infra.remote_client.CCFRemoteClient object at 0x7f36a10cfc50>>
38: └ <infra.remote_client.CCFRemoteClient object at 0x7f36a10cfc50>
38:
38: > File "/home/ci/agent/_work/4/s/tests/infra/remote_client.py", line 100, in wait
38: self.remote.wait_for_stdout_line(line="Global commit", timeout=5)
38: │ │ └ <bound method LocalRemote.wait_for_stdout_line of <infra.remote.LocalRemote object at 0x7f369d24dfd0>>
38: │ └ <infra.remote.LocalRemote object at 0x7f369d24dfd0>
38: └ <infra.remote_client.CCFRemoteClient object at 0x7f36a10cfc50>
38:
38: File "/home/ci/agent/_work/4/s/tests/infra/remote.py", line 360, in wait_for_stdout_line
38: "{} not found in stdout after {} seconds".format(line, timeout)
38: │ └ 5
38: └ 'Global commit'
38:
38: ValueError: Global commit not found in stdout after 5 seconds
38: 2019-06-05 10:44:29.550 | INFO | infra.remote:stop:326 - [127.133.12.129] closing
38: 2019-06-05 10:44:29.556 | INFO | infra.runner:run:137 - Rates: ----------- tx rates -----------
38: ----- mean ----: 9492.643637953652
38: ----- harmonic mean ----: 7938.621457889336
38: ---- standard deviation ----: 1373.4581010981751
38: ----- median ----: 9500
38: ---- max ----: 10777
38: ---- min ----: 83
38: ----------- tx rates histogram -----------
38: {
38: "histogram": {
38: "80..83": 1,
38: "100..103": 1,
38: "108..111": 1,
38: "320..335": 1,
38: "672..703": 1,
38: "992..1023": 3,
38: "1344..1407": 1,
38: "1408..1471": 2,
38: "1664..1727": 1,
38: "1792..1855": 1,
38: "1856..1919": 1,
38: "1984..2047": 1,
38: "2048..2175": 1,
38: "2176..2303": 1,
38: "2688..2815": 4,
38: "2816..2943": 5,
38: "2944..3071": 2,
38: "3072..3199": 1,
38: "3200..3327": 1,
38: "3328..3455": 2,
38: "3456..3583": 2,
38: "3584..3711": 4,
38: "3712..3839": 1,
38: "3840..3967": 2,
38: "4096..4351": 5,
38: "4352..4607": 5,
38: "4608..4863": 4,
38: "4864..5119": 3,
38: "5120..5375": 9,
38: "5376..5631": 5,
38: "5632..5887": 4,
38: "5888..6143": 3,
38: "6144..6399": 6,
38: "6400..6655": 12,
38: "6656..6911": 7,
38: "6912..7167": 9,
38: "7168..7423": 9,
38: "7424..7679": 10,
38: "7680..7935": 20,
38: "7936..8191": 21,
38: "8192..8703": 87,
38: "8704..9215": 201,
38: "9216..9727": 863,
38: "9728..10239": 166,
38: "10240..10751": 795,
38: "10752..11263": 2
38: },
38: "low": 0,
38: "high": 10777,
38: "underflow": 339,
38: "overflow": 0
38: }
38: 2019-06-05 10:44:29.566 | INFO | infra.remote:stop:326 - [127.89.82.26] closing
38: 2019-06-05 10:44:29.583 | ERROR | infra.remote:log_errors:52 - /tmp/ci_0/out: [fail]../src/host/rpcconnections.h:179 - - Cannot close id 3: does not exist
38: 2019-06-05 10:44:29.583 | ERROR | infra.remote:log_errors:57 - /tmp/ci_0/err contents:
38: 2019-06-05 10:44:29.583 | ERROR | infra.remote:log_errors:58 -
38: 2019-06-05 10:44:29.583 | INFO | infra.remote:stop:326 - [127.148.108.186] closing
38: 2019-06-05 10:44:29.615 | INFO | infra.ccf:stop_all_nodes:235 - All remotes stopped...
2/3 Test #38: small_bank_sigs_client_test .............. Passed 34.35 sec
test 39
We need to guarantee to fix this and also make sure that the test fails when this happens.