This issue is related to #3085. When running integration all integration tests in one test test_cli_change_environment_type fails most of the times. When this test runs at the beginning it is more likely to pass.
It runs the Geth Node setup from smoketest.py setup_testchain_and_raiden.
If you want to see logs from geth turn on verbosity to 5 in smoketest.py : 239 and find the corresponding data directoy -> /tmp/tmpXYZ/logs/
then run:
tail -f 0 in that directoy or tail -f /tmp/tmpXYZ/logs/0
Problem Definition
When running integration tests the above test fails frequently. The logs at the bottom give somme inside so far. Since the test fails undeterministically I assume that there are some state changes passed from one test to another.
So far I found out, that finding a new port in setup_testchain_and_raiden always returned 28754 #3098.
PR #3099 fixes that issue.
The actual error happens in web3.py in _compute_gas_price in time_based gas price strategies. It crashes because it could not generate data from the geth client to calculate recommended gas prices.
before (last 100 chars): '104, in _compute_gas_price\r\n first = probabilities[0]\r\nIndexError: tuple index out of range\r\n\x1b[0m'
Geth Clients
In the current version cli tests run smoketest.py setup for geth client. These geth clients are not closed properly after pytest finishes. Instead the process continues to run. Without #3099 these processes are even reused in the next test run. Since cli tests are the only test category using the smoketests setup I assume the cause of the flakiness lies in that function.
command to look for running geth clients and which ports they are using:
netstat -tulpe | grep geth
outcome example:
(Es konnten nicht alle Prozesse identifiziert werden; Informationen über
nicht-eigene Processe werden nicht angezeigt; Root kann sie anzeigen.)
tcp6 0 0 [::]:27854 [::]:* LISTEN fred 547400 16980/geth
tcp6 0 0 [::]:27855 [::]:* LISTEN fred 555060 16980/geth
tcp6 0 0 [::]:27856 [::]:* LISTEN fred 566298 17303/geth
tcp6 0 0 [::]:27857 [::]:* LISTEN fred 563039 17303/geth
tcp6 0 0 [::]:27858 [::]:* LISTEN fred 570319 17506/geth
tcp6 0 0 [::]:27859 [::]:* LISTEN fred 572016 17506/geth
tcp6 0 0 [::]:29994 [::]:* LISTEN fred 700871 21172/geth
tcp6 0 0 [::]:29995 [::]:* LISTEN fred 700869 21172/geth
Logs
TRACE[11-28|08:56:15.000] Waiting for slot to sign and propagate delay=999.030ms
DEBUG[11-28|08:56:15.661] Couldn't add port mapping proto=tcp extport=27855 intport=27855 interface="UPnP or NAT-PMP" err="no UPnP or NAT-PMP router discovered"
DEBUG[11-28|08:56:15.938] Executing EVM call finished runtime=288.099µs
DEBUG[11-28|08:56:15.939] Executing EVM call finished runtime=123.262µs
DEBUG[11-28|08:56:15.939] Executing EVM call finished runtime=107.268µs
DEBUG[11-28|08:56:15.939] Executing EVM call finished runtime=109.273µs
DEBUG[11-28|08:56:15.939] VM returned with error err="contract creation code storage out of gas"
DEBUG[11-28|08:56:15.939] Executing EVM call finished runtime=128.236µs
DEBUG[11-28|08:56:15.939] VM returned with error err="contract creation code storage out of gas"
DEBUG[11-28|08:56:15.939] Executing EVM call finished runtime=143.563µs
DEBUG[11-28|08:56:15.939] VM returned with error err="contract creation code storage out of gas"
DEBUG[11-28|08:56:15.939] Executing EVM call finished runtime=107.174µs
DEBUG[11-28|08:56:15.939] Executing EVM call finished runtime=97.011µs
DEBUG[11-28|08:56:15.939] VM returned with error err="contract creation code storage out of gas"
DEBUG[11-28|08:56:15.939] Executing EVM call finished runtime=115.852µs
DEBUG[11-28|08:56:15.940] Executing EVM call finished runtime=147.302µs
DEBUG[11-28|08:56:15.940] VM returned with error err="contract creation code storage out of gas"
DEBUG[11-28|08:56:15.940] Executing EVM call finished runtime=124.011µs
DEBUG[11-28|08:56:15.940] Executing EVM call finished runtime=136.278µs
DEBUG[11-28|08:56:15.940] Executing EVM call finished runtime=165.91µs
DEBUG[11-28|08:56:15.940] VM returned with error err="contract creation code storage out of gas"
DEBUG[11-28|08:56:15.940] Executing EVM call finished runtime=128.616µs
DEBUG[11-28|08:56:15.940] Executing EVM call finished runtime=154.587µs
DEBUG[11-28|08:56:15.940] VM returned with error err="contract creation code storage out of gas"
DEBUG[11-28|08:56:15.940] Executing EVM call finished runtime=129.547µs
DEBUG[11-28|08:56:15.941] Executing EVM call finished runtime=128.578µs
DEBUG[11-28|08:56:15.941] VM returned with error err="contract creation code storage out of gas"
DEBUG[11-28|08:56:15.941] Executing EVM call finished runtime=134.022µs
DEBUG[11-28|08:56:15.941] Executing EVM call finished runtime=129.655µs
DEBUG[11-28|08:56:15.941] Executing EVM call finished runtime=138.263µs
DEBUG[11-28|08:56:15.941] VM returned with error err="contract creation code storage out of gas"
DEBUG[11-28|08:56:15.941] Executing EVM call finished runtime=134.321µs
DEBUG[11-28|08:56:15.941] VM returned with error err="contract creation code storage out of gas"
DEBUG[11-28|08:56:15.941] Executing EVM call finished runtime=132.614µs
DEBUG[11-28|08:56:15.941] VM returned with error err="contract creation code storage out of gas"
DEBUG[11-28|08:56:15.941] Executing EVM call finished runtime=121.146µs
DEBUG[11-28|08:56:15.942] Executing EVM call finished runtime=133.309µs
TRACE[11-28|08:56:15.955] Pooled new future transaction hash=d4c65b…f77fc2 from=0x67a5E21E34A58eD8D47c719fE291dDD2ea825E12 to=nil
In the raiden logs I found the Invalid LockedTransfer message. Nonce did not change sequentially, expected: 3 got: 1 found in raiden-debug_2018-11-28T08\:53\:57.718195.log
Circle CI gives the following error:
E pexpect.exceptions.EOF: End Of File (EOF). Exception style platform.
E <pexpect.pty_spawn.spawn object at 0x7ff8c44e4128>
E command: /home/circleci/venv-3.6/bin/python
E args: [b'/home/circleci/venv-3.6/bin/python', b'-m', b'raiden', b'--no-sync-check', b'--tokennetwork-registry-contract-address', b'0xd0f0AC47992bBf046e62e03674187Dd4c7A8Ed47', b'--secret-registry-contract-address', b'0xD53fCeDB49b9205777533bcb0af0D83A1d12EBd1', b'--endpoint-registry-contract-address', b'0x99B89AFaa32B156aECb8C83dB80B4b88E48008B9', b'--keystore-path', b'/tmp/tmpil5sxyvb/add4d310/keystore', b'--password-file', b'/tmp/tmpil5sxyvb/pw', b'--datadir', b'/tmp/tmpil5sxyvb/add4d310/keystore', b'--network-id', b'627', b'--eth-rpc-endpoint', b'http://127.0.0.1:27854']
E buffer (last 100 chars): ''
E before (last 100 chars): '104, in _compute_gas_price\r\n first = probabilities[0]\r\nIndexError: tuple index out of range\r\n\x1b[0m'
E after: <class 'pexpect.exceptions.EOF'>
E match: None
E match_index: None
E exitstatus: None
E flag_eof: True
E pid: 993
E child_fd: 24
E closed: False
E timeout: 30
E delimiter: <class 'pexpect.exceptions.EOF'>
E logfile: <_pytest.capture.EncodedFile object at 0x7ff8cf000940>
E logfile_read: None
E logfile_send: None
E maxread: 2000
E ignorecase: False
E searchwindowsize: None
E delaybeforesend: 0.05
E delayafterclose: 0.1
E delayafterterminate: 0.1
E searcher: searcher_re:
E 0: re.compile('Raiden is running in development mode')
../venv-3.6/lib/python3.6/site-packages/pexpect/expect.py:63: EOF
Also raiden-exception
Traceback (most recent call last):
File “/home/circleci/raiden/raiden/ui/runners.py”, line 178, in _start_services
event.get()
File “src/gevent/event.py”, line 381, in gevent._event.AsyncResult.get
File “src/gevent/event.py”, line 409, in gevent._event.AsyncResult.get
File “src/gevent/event.py”, line 399, in gevent._event.AsyncResult.get
File “src/gevent/event.py”, line 379, in gevent._event.AsyncResult._raise_exception
File “/home/circleci/venv-3.7/lib/python3.7/site-packages/gevent/_compat.py”, line 47, in reraise
raise value.with_traceback(tb)
File “src/gevent/greenlet.py”, line 716, in gevent._greenlet.Greenlet.run
File “/home/circleci/raiden/raiden/tasks.py”, line 60, in check_gas_reserve
channels_to_open=0,
File “/home/circleci/raiden/raiden/utils/gas_reserve.py”, line 144, in has_enough_gas_reserve
secure_reserve_estimate = get_reserve_estimate(raiden, channels_to_open)
File “/home/circleci/raiden/raiden/utils/gas_reserve.py”, line 120, in get_reserve_estimate
gas_price = raiden.chain.client.gas_price()
File “/home/circleci/raiden/raiden/network/rpc/client.py”, line 346, in gas_price
return int(self.web3.eth.generateGasPrice())
File “/home/circleci/venv-3.7/lib/python3.7/site-packages/web3/eth.py”, line 385, in generateGasPrice
return self.gasPriceStrategy(self.web3, transaction_params)
File “/home/circleci/venv-3.7/lib/python3.7/site-packages/web3/gas_strategies/time_based.py”, line 168, in time_based_gas_price_strategy
gas_price = _compute_gas_price(probabilities, probability / 100)
File “/home/circleci/venv-3.7/lib/python3.7/site-packages/web3/gas_strategies/time_based.py”, line 104, in _compute_gas_price
first = probabilities[0]
IndexError: tuple index out of range
System Description
It runs my current Pull Request (current master was pulled), GETH_VERSION: '1.8.13', SOLC_VERSION: 'v0.4.23'.
fredo
commented
5 years ago
Intro
This issue is related to #3085. When running integration all integration tests in one test
test_cli_change_environment_typefails most of the times. When this test runs at the beginning it is more likely to pass.running cli-tests alone always passes.
command running all integration tests:
pytest -vvvvvv --log-config='raiden:DEBUG' --random --blockchain-type=geth --transport=udp raiden/tests/integration/command running cli tests:
pytest -vvvvvv --log-config='raiden:DEBUG' --random --blockchain-type=geth --transport=udp raiden/tests/integration/cliIt runs the Geth Node setup from smoketest.py
setup_testchain_and_raiden.If you want to see logs from geth turn on verbosity to 5 in
smoketest.py : 239and find the corresponding data directoy -> /tmp/tmpXYZ/logs/then run:
tail -f 0in that directoy ortail -f /tmp/tmpXYZ/logs/0Problem Definition
When running integration tests the above test fails frequently. The logs at the bottom give somme inside so far. Since the test fails undeterministically I assume that there are some state changes passed from one test to another.
So far I found out, that finding a new port in
setup_testchain_and_raidenalways returned 28754 #3098.PR #3099 fixes that issue.
The actual error happens in web3.py in
_compute_gas_pricein time_based gas price strategies. It crashes because it could not generate data from the geth client to calculate recommended gas prices.before (last 100 chars): '104, in _compute_gas_price\r\n first = probabilities[0]\r\nIndexError: tuple index out of range\r\n\x1b[0m'Geth Clients
In the current version cli tests run smoketest.py setup for geth client. These geth clients are not closed properly after pytest finishes. Instead the process continues to run. Without #3099 these processes are even reused in the next test run. Since cli tests are the only test category using the smoketests setup I assume the cause of the flakiness lies in that function.
command to look for running geth clients and which ports they are using:
netstat -tulpe | grep gethoutcome example:
Logs
In the raiden logs I found the
Invalid LockedTransfer message. Nonce did not change sequentially, expected: 3 got: 1found in raiden-debug_2018-11-28T08\:53\:57.718195.logCircle CI gives the following error:
Also raiden-exception
System Description
It runs my current Pull Request (current master was pulled), GETH_VERSION: '1.8.13', SOLC_VERSION: 'v0.4.23'.