Skip to content
This repository has been archived by the owner on Feb 26, 2024. It is now read-only.

Async/await tests throwing revert error randomly #920

Closed
kermankohli opened this issue Apr 26, 2018 · 30 comments
Closed

Async/await tests throwing revert error randomly #920

kermankohli opened this issue Apr 26, 2018 · 30 comments

Comments

@kermankohli
Copy link

  • [Y] I've asked for help in the Truffle Gitter before filing this issue.

Issue

The following error causes tests to fail randomly.
Error: VM Exception while processing transaction: revert

Steps to Reproduce

It's hard to reproduce although here's a link to the repo:
https://github.com/kermankohli/ethme

Expected Behavior

Tests should consistently pass all the time.

Actual Results

The same test will fail, and then pass when rerun again. It seems to be some kind of caching issue or race condition.

Environment

  • Operating System: Mac OSX
  • Ethereum client: Gananche
  • Truffle version (truffle version): 4.1.7
  • node version (node --version): 9.10.1
  • npm version (npm --version): 5.6.0
@cgewecke
Copy link
Contributor

cgewecke commented Apr 26, 2018

@kermankohli Hi, just peeked at one of your test files and found this. It's a describe block whose callback is async. This isn't compatible with mocha and is a really common source of non-deterministic test behavior. When you're writing using the await pattern it's super easy to do this by accident.

You might comb through the code and make sure everything async/await is as it should be.

@kermankohli
Copy link
Author

Thanks for pointing that out! I removed it (checked for other references) and reran the tests although the same issue still persists:

ethme master ✗ 21h39m ▲ △ ◒ ➜ truffle test
Using network 'development'.

Compiling ./contracts/Authorizable.sol...
Compiling ./contracts/Collectable.sol...
Compiling ./contracts/EightExToken.sol...
Compiling ./contracts/Executor.sol...
Compiling ./contracts/TransferProxy.sol...
Compiling ./contracts/VolumeSubscription.sol...
Compiling ./contracts/base/math/Math.sol...
Compiling ./contracts/base/math/SafeMath.sol...
Compiling ./contracts/base/ownership/Ownable.sol...
Compiling ./contracts/base/token/BasicToken.sol...
Compiling ./contracts/base/token/ERC20.sol...
Compiling ./contracts/base/token/ERC20Basic.sol...
Compiling ./contracts/base/token/StandardToken.sol...

Compilation warnings encountered:

/Users/kermankohli/crypto/ethme/contracts/base/ownership/Ownable.sol:19:5: Warning: Defining constructors as functions with the same name as the contract is deprecated. Use "constructor(...) { ... }" instead.
    function Ownable() public {
    ^ (Relevant source part starts here and spans across multiple lines).
,/Users/kermankohli/crypto/ethme/contracts/Collectable.sol:22:5: Warning: Modifiers of functions without implementation are ignored.
    function subscriptionOwnerDoesntHaveEnoughFunds(bytes32 _subscription) onlyAuthorized public;
    ^-------------------------------------------------------------------------------------------^
,/Users/kermankohli/crypto/ethme/contracts/EightExToken.sol:15:5: Warning: Defining constructors as functions with the same name as the contract is deprecated. Use "constructor(...) { ... }" instead.
    function EightExToken() public {
    ^ (Relevant source part starts here and spans across multiple lines).
,/Users/kermankohli/crypto/ethme/contracts/EightExToken.sol:40:13: Warning: Invoking events without "emit" prefix is deprecated.
            Transfer(_from, _to, _value);
            ^--------------------------^



  Contract: TransferProxy
    ✓ should throw if an unauthorized address tries to transfer tokens (113ms)
    ✓ should allow an authorized address to transfer tokens (329ms)

  Contract: VolumeSubscription
    ✓ should be able to intialise the plan contract correctly (46ms)
    ✓ should have the correct computed plan hash (133ms)
    1) should have the correct computed subscription hash
    > No events were emitted
    when collecting money from the contract
      2) should be able to terminate as an authorized address

    Events emitted during test:
    ---------------------------

    CreatedPlan(identifier: 0x10da531567bebf1fcb02b8f726c730b789279cd0e337402343f0a6f69903eb30)
    CreatedSubscription(identifier: 0x0482a2203bdfb9455f174311fc04f67ec2c768dc71a12ceba9ed4806c8eeaa29)
    LogAuthorizedAddressAdded(target: <indexed>, caller: <indexed>)
    TerminatedSubscription(identifier: 0x0482a2203bdfb9455f174311fc04f67ec2c768dc71a12ceba9ed4806c8eeaa29, terminationDate: 1524724896)

    ---------------------------
      ✓ should be not be able to terminate as an unauthorized address (164ms)
      ✓ should be able to determine a valid subscription (243ms)
      ✓ should be able to determine an invalid subscription (403ms)
      3) should be able to get the correct amount

    Events emitted during test:
    ---------------------------

    CreatedPlan(identifier: 0x35481ef21398e15e1d6ca5f49401cb5a8a84df62305f7f478da6742402c97f8a)

    ---------------------------
    when creating a new plan
      ✓ should be able to create a new plan correctly (104ms)
      ✓ should not be able to create a plan without required details (195ms)
      ✓ should not be able to create a plan with the same identifier (128ms)
    when updating the owner of a plan
      ✓ should be able to update as the owner (307ms)
      ✓ should be not be able to update the owner as another user (84ms)
    when updating the name of a plan
      ✓ should be able to update as the owner (290ms)
      ✓ should be not be able to update as another user (153ms)
    when updating the description of a plan
      ✓ should be able to update as the owner (197ms)
      ✓ should be not be able to update as another user (165ms)
    when updating the data of a plan
      ✓ should be able to update as the owner (189ms)
      ✓ should be not be able to update as another user (92ms)
    when terminating a plan
      ✓ should be able to terminate as the owner (258ms)
      ✓ should not be able to terminate multiple times (199ms)
      ✓ should not be able to terminate from a date in the past (155ms)
      ✓ should not be able to terminate as another user (169ms)
    when updating the data of a subscription
      ✓ should be able to update as the owner (321ms)
      ✓ should be not be able to update as another user (280ms)
    when terminating a subscription
      ✓ should be able to terminate as the owner (320ms)
      ✓ should not be able to terminate multiple times (288ms)
      ✓ should not be able to terminate from a date in the past (201ms)
      ✓ should not be able to terminate as another user (214ms)

  Contract: Authorizable
    when adding an authorized address
      ✓ should throw if not called by the owner (64ms)
      ✓ should allow the owner to add an authorized address (203ms)
      ✓ should not allow an authorized address to add a duplicate address
    when removing an authorized address
      ✓ should throw if not called by the owner (61ms)
      ✓ should allow the owner to remove an authorized address (151ms)
      ✓ should now allow the owner to remove a non-authorized address
    when getting authorized addresses
      ✓ should be able to return all the authorized addresses (250ms)


  35 passing (8s)
  3 failing

  1) Contract: VolumeSubscription should have the correct computed subscription hash:
     Error: VM Exception while processing transaction: revert
      at Object.InvalidResponse (/usr/local/lib/node_modules/truffle/build/webpack:/~/web3/lib/web3/errors.js:38:1)
      at /usr/local/lib/node_modules/truffle/build/webpack:/~/web3/lib/web3/requestmanager.js:86:1
      at /usr/local/lib/node_modules/truffle/build/webpack:/~/truffle-provider/wrapper.js:134:1
      at XMLHttpRequest.request.onreadystatechange (/usr/local/lib/node_modules/truffle/build/webpack:/~/web3/lib/web3/httpprovider.js:128:1)
      at XMLHttpRequestEventTarget.dispatchEvent (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:64:1)
      at XMLHttpRequest._setReadyState (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:354:1)
      at XMLHttpRequest._onHttpResponseEnd (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:509:1)
      at IncomingMessage.<anonymous> (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:469:1)
      at endReadableNT (_stream_readable.js:1106:12)
      at process._tickCallback (internal/process/next_tick.js:114:19)

  2) Contract: VolumeSubscription when collecting money from the contract should be able to terminate as an authorized address:
     AssertionError: expected { Object (s, e, ...) } to equal 1524724895
      at Context._callee3$ (test/volume_subscription.js:44:20)
      at tryCatch (node_modules/regenerator-runtime/runtime.js:65:40)
      at Generator.invoke [as _invoke] (node_modules/regenerator-runtime/runtime.js:303:22)
      at Generator.prototype.(anonymous function) [as next] (node_modules/regenerator-runtime/runtime.js:117:21)
      at step (test/volume_subscription.js:15:191)
      at test/volume_subscription.js:15:361
      at <anonymous>
      at process._tickCallback (internal/process/next_tick.js:118:7)

  3) Contract: VolumeSubscription when collecting money from the contract should be able to get the correct amount:
     Error: VM Exception while processing transaction: revert
      at Object.InvalidResponse (/usr/local/lib/node_modules/truffle/build/webpack:/~/web3/lib/web3/errors.js:38:1)
      at /usr/local/lib/node_modules/truffle/build/webpack:/~/web3/lib/web3/requestmanager.js:86:1
      at /usr/local/lib/node_modules/truffle/build/webpack:/~/truffle-provider/wrapper.js:134:1
      at XMLHttpRequest.request.onreadystatechange (/usr/local/lib/node_modules/truffle/build/webpack:/~/web3/lib/web3/httpprovider.js:128:1)
      at XMLHttpRequestEventTarget.dispatchEvent (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:64:1)
      at XMLHttpRequest._setReadyState (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:354:1)
      at XMLHttpRequest._onHttpResponseEnd (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:509:1)
      at IncomingMessage.<anonymous> (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:469:1)
      at endReadableNT (_stream_readable.js:1106:12)
      at process._tickCallback (internal/process/next_tick.js:114:19)



ethme master ✗ 21h39m ▲ △ ◒ ⍉ ➜ truffle test
Using network 'development'.

Compiling ./contracts/Authorizable.sol...
Compiling ./contracts/Collectable.sol...
Compiling ./contracts/EightExToken.sol...
Compiling ./contracts/Executor.sol...
Compiling ./contracts/TransferProxy.sol...
Compiling ./contracts/VolumeSubscription.sol...
Compiling ./contracts/base/math/Math.sol...
Compiling ./contracts/base/math/SafeMath.sol...
Compiling ./contracts/base/ownership/Ownable.sol...
Compiling ./contracts/base/token/BasicToken.sol...
Compiling ./contracts/base/token/ERC20.sol...
Compiling ./contracts/base/token/ERC20Basic.sol...
Compiling ./contracts/base/token/StandardToken.sol...

Compilation warnings encountered:

/Users/kermankohli/crypto/ethme/contracts/base/ownership/Ownable.sol:19:5: Warning: Defining constructors as functions with the same name as the contract is deprecated. Use "constructor(...) { ... }" instead.
    function Ownable() public {
    ^ (Relevant source part starts here and spans across multiple lines).
,/Users/kermankohli/crypto/ethme/contracts/Collectable.sol:22:5: Warning: Modifiers of functions without implementation are ignored.
    function subscriptionOwnerDoesntHaveEnoughFunds(bytes32 _subscription) onlyAuthorized public;
    ^-------------------------------------------------------------------------------------------^
,/Users/kermankohli/crypto/ethme/contracts/EightExToken.sol:15:5: Warning: Defining constructors as functions with the same name as the contract is deprecated. Use "constructor(...) { ... }" instead.
    function EightExToken() public {
    ^ (Relevant source part starts here and spans across multiple lines).
,/Users/kermankohli/crypto/ethme/contracts/EightExToken.sol:40:13: Warning: Invoking events without "emit" prefix is deprecated.
            Transfer(_from, _to, _value);
            ^--------------------------^



  Contract: Authorizable
    when adding an authorized address
      ✓ should throw if not called by the owner
      ✓ should allow the owner to add an authorized address (94ms)
      ✓ should not allow an authorized address to add a duplicate address
    when removing an authorized address
      ✓ should throw if not called by the owner
      ✓ should allow the owner to remove an authorized address (97ms)
      ✓ should now allow the owner to remove a non-authorized address (59ms)
    when getting authorized addresses
      ✓ should be able to return all the authorized addresses (246ms)

  Contract: TransferProxy
    ✓ should throw if an unauthorized address tries to transfer tokens (121ms)
    ✓ should allow an authorized address to transfer tokens (407ms)

  Contract: VolumeSubscription
    ✓ should be able to intialise the plan contract correctly
    ✓ should have the correct computed plan hash (92ms)
    1) should have the correct computed subscription hash
    > No events were emitted
    when collecting money from the contract
      2) should be able to terminate as an authorized address

    Events emitted during test:
    ---------------------------

    CreatedPlan(identifier: 0x10da531567bebf1fcb02b8f726c730b789279cd0e337402343f0a6f69903eb30)

    ---------------------------
      ✓ should be not be able to terminate as an unauthorized address (210ms)
      ✓ should be able to determine a valid subscription (241ms)
      ✓ should be able to determine an invalid subscription (405ms)
      ✓ should be able to get the correct amount (216ms)
    when creating a new plan
      ✓ should be able to create a new plan correctly (98ms)
      ✓ should not be able to create a plan without required details (197ms)
      ✓ should not be able to create a plan with the same identifier (158ms)
    when updating the owner of a plan
      ✓ should be able to update as the owner (274ms)
      ✓ should be not be able to update the owner as another user (96ms)
    when updating the name of a plan
      ✓ should be able to update as the owner (258ms)
      ✓ should be not be able to update as another user (83ms)
    when updating the description of a plan
      ✓ should be able to update as the owner (260ms)
      ✓ should be not be able to update as another user (89ms)
    when updating the data of a plan
      ✓ should be able to update as the owner (277ms)
      ✓ should be not be able to update as another user (124ms)
    when terminating a plan
      ✓ should be able to terminate as the owner (191ms)
      ✓ should not be able to terminate multiple times (208ms)
      ✓ should not be able to terminate from a date in the past (123ms)
      ✓ should not be able to terminate as another user (151ms)
    when updating the data of a subscription
      ✓ should be able to update as the owner (308ms)
      ✓ should be not be able to update as another user (219ms)
    when terminating a subscription
      ✓ should be able to terminate as the owner (310ms)
      3) should not be able to terminate multiple times

    Events emitted during test:
    ---------------------------

    CreatedPlan(identifier: 0x5e5508da6762220619aeda638dcb0b33546297cc03cd1fb9fcb81167bf3183bd)

    ---------------------------
      ✓ should not be able to terminate from a date in the past (223ms)
      ✓ should not be able to terminate as another user (211ms)


  35 passing (8s)
  3 failing

  1) Contract: VolumeSubscription should have the correct computed subscription hash:
     Error: VM Exception while processing transaction: revert
      at Object.InvalidResponse (/usr/local/lib/node_modules/truffle/build/webpack:/~/web3/lib/web3/errors.js:38:1)
      at /usr/local/lib/node_modules/truffle/build/webpack:/~/web3/lib/web3/requestmanager.js:86:1
      at /usr/local/lib/node_modules/truffle/build/webpack:/~/truffle-provider/wrapper.js:134:1
      at XMLHttpRequest.request.onreadystatechange (/usr/local/lib/node_modules/truffle/build/webpack:/~/web3/lib/web3/httpprovider.js:128:1)
      at XMLHttpRequestEventTarget.dispatchEvent (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:64:1)
      at XMLHttpRequest._setReadyState (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:354:1)
      at XMLHttpRequest._onHttpResponseEnd (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:509:1)
      at IncomingMessage.<anonymous> (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:469:1)
      at endReadableNT (_stream_readable.js:1106:12)
      at process._tickCallback (internal/process/next_tick.js:114:19)

  2) Contract: VolumeSubscription when collecting money from the contract should be able to terminate as an authorized address:
     Error: VM Exception while processing transaction: revert
      at Object.InvalidResponse (/usr/local/lib/node_modules/truffle/build/webpack:/~/web3/lib/web3/errors.js:38:1)
      at /usr/local/lib/node_modules/truffle/build/webpack:/~/web3/lib/web3/requestmanager.js:86:1
      at /usr/local/lib/node_modules/truffle/build/webpack:/~/truffle-provider/wrapper.js:134:1
      at XMLHttpRequest.request.onreadystatechange (/usr/local/lib/node_modules/truffle/build/webpack:/~/web3/lib/web3/httpprovider.js:128:1)
      at XMLHttpRequestEventTarget.dispatchEvent (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:64:1)
      at XMLHttpRequest._setReadyState (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:354:1)
      at XMLHttpRequest._onHttpResponseEnd (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:509:1)
      at IncomingMessage.<anonymous> (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:469:1)
      at endReadableNT (_stream_readable.js:1106:12)
      at process._tickCallback (internal/process/next_tick.js:114:19)

  3) Contract: VolumeSubscription when terminating a subscription should not be able to terminate multiple times:
     Error: VM Exception while processing transaction: revert
      at Object.InvalidResponse (/usr/local/lib/node_modules/truffle/build/webpack:/~/web3/lib/web3/errors.js:38:1)
      at /usr/local/lib/node_modules/truffle/build/webpack:/~/web3/lib/web3/requestmanager.js:86:1
      at /usr/local/lib/node_modules/truffle/build/webpack:/~/truffle-provider/wrapper.js:134:1
      at XMLHttpRequest.request.onreadystatechange (/usr/local/lib/node_modules/truffle/build/webpack:/~/web3/lib/web3/httpprovider.js:128:1)
      at XMLHttpRequestEventTarget.dispatchEvent (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:64:1)
      at XMLHttpRequest._setReadyState (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:354:1)
      at XMLHttpRequest._onHttpResponseEnd (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:509:1)
      at IncomingMessage.<anonymous> (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:469:1)
      at endReadableNT (_stream_readable.js:1106:12)
      at process._tickCallback (internal/process/next_tick.js:114:19)



ethme master ✗ 21h39m ▲ △ ◒ ⍉ ➜ truffle test
Using network 'development'.

Compiling ./contracts/Authorizable.sol...
Compiling ./contracts/Collectable.sol...
Compiling ./contracts/EightExToken.sol...
Compiling ./contracts/Executor.sol...
Compiling ./contracts/TransferProxy.sol...
Compiling ./contracts/VolumeSubscription.sol...
Compiling ./contracts/base/math/Math.sol...
Compiling ./contracts/base/math/SafeMath.sol...
Compiling ./contracts/base/ownership/Ownable.sol...
Compiling ./contracts/base/token/BasicToken.sol...
Compiling ./contracts/base/token/ERC20.sol...
Compiling ./contracts/base/token/ERC20Basic.sol...
Compiling ./contracts/base/token/StandardToken.sol...

Compilation warnings encountered:

/Users/kermankohli/crypto/ethme/contracts/base/ownership/Ownable.sol:19:5: Warning: Defining constructors as functions with the same name as the contract is deprecated. Use "constructor(...) { ... }" instead.
    function Ownable() public {
    ^ (Relevant source part starts here and spans across multiple lines).
,/Users/kermankohli/crypto/ethme/contracts/Collectable.sol:22:5: Warning: Modifiers of functions without implementation are ignored.
    function subscriptionOwnerDoesntHaveEnoughFunds(bytes32 _subscription) onlyAuthorized public;
    ^-------------------------------------------------------------------------------------------^
,/Users/kermankohli/crypto/ethme/contracts/EightExToken.sol:15:5: Warning: Defining constructors as functions with the same name as the contract is deprecated. Use "constructor(...) { ... }" instead.
    function EightExToken() public {
    ^ (Relevant source part starts here and spans across multiple lines).
,/Users/kermankohli/crypto/ethme/contracts/EightExToken.sol:40:13: Warning: Invoking events without "emit" prefix is deprecated.
            Transfer(_from, _to, _value);
            ^--------------------------^



  Contract: Authorizable
    when adding an authorized address
      ✓ should throw if not called by the owner
      ✓ should allow the owner to add an authorized address (127ms)
      ✓ should not allow an authorized address to add a duplicate address
    when removing an authorized address
      ✓ should throw if not called by the owner
      ✓ should allow the owner to remove an authorized address (94ms)
      ✓ should now allow the owner to remove a non-authorized address
    when getting authorized addresses
      ✓ should be able to return all the authorized addresses (188ms)

  Contract: TransferProxy
    ✓ should throw if an unauthorized address tries to transfer tokens (123ms)
    ✓ should allow an authorized address to transfer tokens (364ms)

  Contract: VolumeSubscription
    ✓ should be able to intialise the plan contract correctly
    ✓ should have the correct computed plan hash (89ms)
    1) should have the correct computed subscription hash
    > No events were emitted
    when collecting money from the contract
      ✓ should be able to terminate as an authorized address (426ms)
      ✓ should be not be able to terminate as an unauthorized address (223ms)
      ✓ should be able to determine a valid subscription (205ms)
      ✓ should be able to determine an invalid subscription (290ms)
      ✓ should be able to get the correct amount (203ms)
    when creating a new plan
      ✓ should be able to create a new plan correctly (108ms)
      ✓ should not be able to create a plan without required details (188ms)
      ✓ should not be able to create a plan with the same identifier (186ms)
    when updating the owner of a plan
      ✓ should be able to update as the owner (284ms)
      ✓ should be not be able to update the owner as another user (159ms)
    when updating the name of a plan
      ✓ should be able to update as the owner (243ms)
      ✓ should be not be able to update as another user (127ms)
    when updating the description of a plan
      ✓ should be able to update as the owner (185ms)
      ✓ should be not be able to update as another user (119ms)
    when updating the data of a plan
      ✓ should be able to update as the owner (193ms)
      ✓ should be not be able to update as another user (87ms)
    when terminating a plan
      ✓ should be able to terminate as the owner (203ms)
      ✓ should not be able to terminate multiple times (201ms)
      ✓ should not be able to terminate from a date in the past (236ms)
      ✓ should not be able to terminate as another user (182ms)
    when updating the data of a subscription
      ✓ should be able to update as the owner (286ms)
      ✓ should be not be able to update as another user (212ms)
    when terminating a subscription
      ✓ should be able to terminate as the owner (312ms)
      2) should not be able to terminate multiple times

    Events emitted during test:
    ---------------------------

    CreatedPlan(identifier: 0x5e5508da6762220619aeda638dcb0b33546297cc03cd1fb9fcb81167bf3183bd)

    ---------------------------
      ✓ should not be able to terminate from a date in the past (212ms)
      ✓ should not be able to terminate as another user (209ms)


  36 passing (8s)
  2 failing

  1) Contract: VolumeSubscription should have the correct computed subscription hash:
     Error: VM Exception while processing transaction: revert
      at Object.InvalidResponse (/usr/local/lib/node_modules/truffle/build/webpack:/~/web3/lib/web3/errors.js:38:1)
      at /usr/local/lib/node_modules/truffle/build/webpack:/~/web3/lib/web3/requestmanager.js:86:1
      at /usr/local/lib/node_modules/truffle/build/webpack:/~/truffle-provider/wrapper.js:134:1
      at XMLHttpRequest.request.onreadystatechange (/usr/local/lib/node_modules/truffle/build/webpack:/~/web3/lib/web3/httpprovider.js:128:1)
      at XMLHttpRequestEventTarget.dispatchEvent (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:64:1)
      at XMLHttpRequest._setReadyState (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:354:1)
      at XMLHttpRequest._onHttpResponseEnd (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:509:1)
      at IncomingMessage.<anonymous> (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:469:1)
      at endReadableNT (_stream_readable.js:1106:12)
      at process._tickCallback (internal/process/next_tick.js:114:19)

  2) Contract: VolumeSubscription when terminating a subscription should not be able to terminate multiple times:
     Error: VM Exception while processing transaction: revert
      at Object.InvalidResponse (/usr/local/lib/node_modules/truffle/build/webpack:/~/web3/lib/web3/errors.js:38:1)
      at /usr/local/lib/node_modules/truffle/build/webpack:/~/web3/lib/web3/requestmanager.js:86:1
      at /usr/local/lib/node_modules/truffle/build/webpack:/~/truffle-provider/wrapper.js:134:1
      at XMLHttpRequest.request.onreadystatechange (/usr/local/lib/node_modules/truffle/build/webpack:/~/web3/lib/web3/httpprovider.js:128:1)
      at XMLHttpRequestEventTarget.dispatchEvent (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:64:1)
      at XMLHttpRequest._setReadyState (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:354:1)
      at XMLHttpRequest._onHttpResponseEnd (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:509:1)
      at IncomingMessage.<anonymous> (/usr/local/lib/node_modules/truffle/build/webpack:/~/xhr2/lib/xhr2.js:469:1)
      at endReadableNT (_stream_readable.js:1106:12)
      at process._tickCallback (internal/process/next_tick.js:114:19)



ethme master ✗ 21h40m ▲ △ ◒ ⍉ ➜ 

@kermankohli
Copy link
Author

All those 3 tests were run straight after each other. Only the computed subscription hash test consistently fails.

@cgewecke
Copy link
Contributor

@kermankohli I wonder if it's related to the mix of it and describe blocks in that suite. should have correct computed hash sits in it's own async it, while the tests around it are encapsulated in sync describe blocks. The contract is being created once at the top of the file in a before, so the tests all share that object and its state is changed over the course of the VolumeSubscription suite.

If you change before to beforeEach (not sure that's feasible in your case) does that normalize the run? If so wrapping singleton its' in a describe might also help.

@kermankohli
Copy link
Author

So I just tried getting rid of single it blocks and wrapping them in describes. Also changed before to beforeEach. Both of these still yield the same results of the tests randomly failing...

@cgewecke
Copy link
Contributor

@kermankohli Mmmm. Maybe something about the way the times are being computed? What if you slow those tests way down by inserting at the top of each?

await setTimeout(() => new Promise((accept) => accept()), 1000)  // Or something like this . . .

@kermankohli
Copy link
Author

kermankohli commented Apr 26, 2018

Okay so gave that a go and the same 12 tests fail which is good since at leas there's consistency in what's not working. Although still not sure what exactly is going on here.

await new Promise(resolve => setTimeout(resolve, 1000)); worked instead ;)

@cgewecke
Copy link
Contributor

Lol ok great!

@kermankohli
Copy link
Author

Kind of - although why do you think the tests are failing randomly unless I have the delay? Can't see what's causing the race condition in this case.

@cgewecke
Copy link
Contributor

@kermankohli I don't know - it must be something about the time values as they execute. Maybe the resolution is too low? If you put logging statements in to see what they are, the bug would probably go away too because those introduce their own delay.

@kermankohli
Copy link
Author

The time values for when the subscription is being created or you mean something else? Apart from logging is there any cleaner way of doing this? Although throughout my program, all the time logic is to check a date in the past so I'm not sure how it's caused a race condition to occur.

@cgewecke
Copy link
Contributor

@kermankohli Does the contract rely on the block timestamp or now to evaluate past and future?

@kermankohli
Copy link
Author

Yup. In VolumeSubscription there's statements such as:
subscriptions[_subscription].terminationDate = block.timestamp;
and require(_terminationDate >= block.timestamp);

@cgewecke
Copy link
Contributor

@kermankohli Yes - this is a big issue. Effective resolution for block.timestamp is the amount of time it takes to mine a block. On mainnet 'many' seconds, on the test client, milliseconds. Ultimately the contract's idea of what time it is determines whether or not that require statement is true or not.

@kermankohli
Copy link
Author

So essentially the time taken to mine the block may be greater than the existing time captured in Javascript?

@cgewecke
Copy link
Contributor

cgewecke commented Apr 26, 2018

There's some information about on how Solidity thinks block.timestamp should be understood. It also looks like the expected precision is 1 second and believe that ganache respects that so suggestion above about ms is just wrong.

The safest thing might be to fetch the current block, read the timestamp, and generate a timestamp that is definitely earlier (or later) than what ganache thinks the time is.

@cgewecke
Copy link
Contributor

@kermankohli This is a very interesting topic today - more in depth discussion at #921 as well.

@cgewecke
Copy link
Contributor

@kermankohli Should we keep this open?

@kermankohli
Copy link
Author

@cgewecke Not sure to be honest. Theoretically the only test that should be failing are the ones that are ones that rely on time logic. However there's tests which simply read data and fail due to revert. The only explanation I can see for it is that the revert is being called at an incorrect place in the test execution hence giving a "random" error variance.

@cgewecke cgewecke changed the title Error: VM Exception while processing transaction: revert Async/await tests throwing revert error randomly Apr 28, 2018
@cgewecke
Copy link
Contributor

@kermankohli Ok, I'm going to rename this issue a little to narrow its scope. Please ping or close if you discover something.

@cgewecke
Copy link
Contributor

cgewecke commented May 7, 2018

@kermankohli Did you ever get to the bottom of this?

@kermankohli
Copy link
Author

@cgewecke yup finally did 3 days ago! so essentially when require statements are dependent on time they can cause failures at places which seem random. the way i solved this was create a mock contract that inherited from the actual contract and overrides a currentTimestamp() function of the actual contract to change the time to whatever I want. you can check it out at: https://github.com/8x-protocol/8x-protocol :)

@cgewecke
Copy link
Contributor

cgewecke commented May 8, 2018

Ok, well thanks for opening - I'm sure this will be helpful to others. Closing since you found a way out.

@cgewecke cgewecke closed this as completed May 8, 2018
@barakman
Copy link

barakman commented May 8, 2018

@kermankohli - side note:

I believe that you have a logical error in file https://github.com/8x-protocol/8x-protocol/blob/master/test/helpers/assert_revert.js.

If promise is completed successfully, then you throw an exception with an error message containing "revert".

You then catch this error, and since its message contains "revert", you determine that the test has completed successfully.

Instead, I suggest that you throw null, and then first thing inside the catch, you do:

assert(error, 'Expected an error containing "revert" but did not get any');

@kermankohli
Copy link
Author

@barakman thanks for that although not sure what you mean. the function is meant to throw an exception if the promise executes since we didn't want it to execute in the first place. feel free to correct me if i'm wrong/misunderstanding you though :)

@barakman
Copy link

barakman commented May 8, 2018

@kermankohli:
Exactly, but this exception is thrown in the try part and caught in the catch part.
Then, in the catch part, you throw another exception, and that exception is the one that will eventually indicate whether the test has succeeded or failed.
Now, take a look at that exception (the one thrown from inside the catch part) - it is thrown only if the error message does not contain "revert".

So, let's analyze a scenario in which the promise completes successfully, hence the test should fail:

  • In the try part, the promise completes successfully
  • In the try part, you throw an exception with "revert" in its error message
  • In the catch part, you detect "revert" in the error message and do not throw an exception
  • No exception is thrown, and the test completes successfully

In order to understand the logical confusion, keep in mind that there are two different failure scenarios which you need to detect and handle:

  1. No error has occurred (the promise has completed successfully)
  2. An error without "revert" has occurred (the promise has failed but not because of require)

In your code, I believe that you detect the first scenario correctly, but you handle it incorrectly.

@kermankohli
Copy link
Author

@barakman ah - i get what you're saying although the "assert.throw" shows in the console and fails the tests so it doesn't matter if the catch block marks it as a success since it's already failed. i've manually tested out the code by providing it passing and failing conditions and it works as expected. also, the code is actually from OpenZepelin so might be worth discussing it with them however you should create a demo project and test it out for yourself first https://github.com/OpenZeppelin/openzeppelin-solidity/blob/master/test/helpers/assertRevert.js.

@barakman
Copy link

barakman commented May 9, 2018

@kermankohli:

OK, perhaps I am missing something.

The thing to understand is that the Mocha framework reports a failure only when your test (it) throws an exception.
When that happens, the Mocha framework catches this exception and reports failure on the specific test at hand.
When you throw an exception and immediately catch it, the Mocha framework is not even aware of it.

That said, here is my analysis of your code and why I think it handles a specific scenario incorrectly:

try { // an exception will be thrown from inside this 'try' clause for sure
  await promise; // either here (if the promise has failed)
  assert.fail('Expected revert not received'); // or here (if the promise has succeeded)
} catch (error) { // but this exception will be immediately caught inside this 'catch' clause
  const revertFound = error.message.search('revert') >= 0;
  assert(revertFound, `Expected "revert", got ${error} instead`);
}

Now, let's analyze the catch clause:

  • An exception will be thrown by the assert only if 'revert' is not found in the error message.
  • If no exception is thrown, then the Mocha framework will report success on the given test.
  • When the promise succeeds, the error message is 'Expected revert not received', hence contains 'revert'.
  • Hence no exception is thrown and the test will succeed although it should fail because the promise succeeded.

In any case, I have posted it on Zeppelin GIT as well (here).

@cgewecke
Copy link
Contributor

cgewecke commented May 9, 2018

@barakman Nice catch!!

@barakman
Copy link

@cgewecke: Thank you, but keep in mind that the catch is where the actual problem hides in this case.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants