TestInvalidExit failure case(PETH balance mismatch)

[modagi]

TestInvalidExit in pls sometimes failed like below.

System information

Geth version:

Version: 1.9.1-stable
Git Commit: 4bf7d7e315e19a2b31683935e866ae952b32ab7d
Git Commit Date: 20200406
Architecture: amd64
Protocol Versions: [63]
Network Id: 1
Go Version: go1.14
Operating System: linux
GOPATH=
GOROOT=/usr/lib/go-1.14

plasma-evm version:

Version: 1.9.10-stable
Git Commit: 3fd45f8a7ad8f478c23ad1a0587e12ae2a824e99
Git Commit Date: 20200520
Architecture: amd64
Protocol Versions: [64 63]
Go Version: go1.14
Operating System: linux
GOPATH=
GOROOT=/usr/lib/go-1.14

OS & Version: Ubuntu 18.04.1 LTS
Commit hash : 3fd45f8

Expected behaviour

Pass test TestInvalidExit

Actual behaviour

Sometimes fail

Steps to reproduce the behaviour

go test -v --timeout 3600s ./pls -run TestInvalidExit

Backtrace

...
INFO [06-15|00:43:14.005|tx/manager.go:779]                  New root chain block mined               number=595 numTxs=0 gasUsed=0      gasLimit=100000000
DEBUG[06-15|00:43:14.009|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(3: [3-4])"
INFO [06-15|00:43:15.007|tx/manager.go:779]                  New root chain block mined               number=596 numTxs=0 gasUsed=0      gasLimit=100000000
DEBUG[06-15|00:43:15.010|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(3: [3-4])"
DEBUG[06-15|00:43:15.199|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(3: [3-4])"
WARN [06-15|00:43:15.864|pls/rootchain_manager_test.go:2577] Check mined block                        expectedBlockNumber=5
DEBUG[06-15|00:43:15.864|rpc/handler.go:302]                 Served eth_getTransactionReceipt         reqid=18 t=102.471µs
INFO [06-15|00:43:15.865|miner/unconfirmed.go:85]            🔨 mined potential block                  number=5   hash=443163…0ad8f1
INFO [06-15|00:43:15.865|miner/worker.go:635]                Successfully sealed new block            number=6   sealhash=e41db9…1aeea1 hash=1d80e3…bb9d0c elapsed=8.853s
DEBUG[06-15|00:43:15.865|rpc/handler.go:302]                 Served eth_getTransactionReceipt         reqid=19 t=83.482µs
INFO [06-15|00:43:15.865|pls/rootchain_manager.go:659]       New request block is mined               blockNumber=5   txs=4
INFO [06-15|00:43:15.865|pls/rootchain_manager.go:533]       RootChain epoch prepared                 epochNumber=5 startBlockNumber=6 endBlockNumber=7 epochLength=2 isRequest=false userActivated=false isEmpty=false ForkNumber=0 isRebase=false
INFO [06-15|00:43:15.865|miner/miner.go:180]                 NRB epoch is prepared, NRB epoch is started epochLength=2
DEBUG[06-15|00:43:15.866|core/tx_pool.go:1254]               Reinjecting stale transactions           count=0
INFO [06-15|00:43:15.866|pls/rootchain_manager.go:424]       New block is mined                       number=6
DEBUG[06-15|00:43:15.867|rpc/handler.go:302]                 Served eth_getTransactionReceipt         reqid=20 t=59.888µs
DEBUG[06-15|00:43:15.867|rpc/handler.go:302]                 Served eth_getTransactionReceipt         reqid=21 t=63.17µs
WARN [06-15|00:43:15.868|pls/rootchain_manager_test.go:2600] Check Block Number                       expectedBlockNumber=5 minedBlockNumber=5 forkNumber=1
WARN [06-15|00:43:15.868|pls/rootchain_manager_test.go:2626] Check mined block                        expectedBlockNumber=5
WARN [06-15|00:43:15.868|pls/rootchain_manager_test.go:2640] Check Submitted Block Number             expectedBlockNumber=5 minedBlockNumber=5 forkNumber=1
WARN [06-15|00:43:15.869|pls/rootchain_manager_test.go:2678] Check epoch after submission             expectedEpochNumber=4
INFO [06-15|00:43:15.870|pls/rootchain_manager_test.go:2686] Next prepared epoch                      e="&{ForkNumber:+0 EpochNumber:+5 StartBlockNumber:+6 EndBlockNumber:+7 RequestStart:+0 RequestEnd:+0 EpochIsEmpty:false IsRequest:false UserActivated:false Rebase:false Raw:{Address:[21 41 76 48 113 1 112 6 24 207 201 161 54 64 150 205 208 158 91 40] Topics:[[26 105 192 118 10 163 41 183 111 114 87 145 41 134 144 19 235 211 212 21 148 219 1 156 14 153 123 147 159 203 50 227]] Data:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 5 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 6 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 7 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] BlockNumber:590 TxHash:[160 110 245 25 118 21 223 173 244 254 88 83 233 227 69 116 249 146 130 220 19 112 166 64 7 63 202 114 31 72 228 101] TxIndex:0 BlockHash:[227 165 123 90 91 159 39 250 77 197 235 115 152 109 37 203 41 8 109 142 117 230 31 227 108 68 149 11 86 184 24 222] Index:1 Removed:false}}"
ERROR[06-15|00:43:15.871|pls/rootchain_manager.go:433]       Failed to get balance of operator account from rootchain err="json: cannot unmarshal hex number > 256 bits into Go value of type *hexutil.Big"
WARN [06-15|00:43:15.871|pls/rootchain_manager.go:437]       Operator account balance on rootchain is too low
INFO [06-15|00:43:15.871|pls/rootchain_manager.go:456]       Non-request epoch is not completed yet   epochNumber=5
WARN [06-15|00:43:15.872|pls/rootchain_manager_test.go:2697] Epoch?                                   e="{StartBlockNumber:5 EndBlockNumber:5 Timestamp:1592181777 IsEmpty:false Initialized:true IsRequest:true UserActivated:false Rebase:false RE:{RequestStart:0 RequestEnd:3 FirstRequestBlockId:0 NumEnter:8 NextEnterEpoch:0 NextEpoch:0} NRE:{EpochStateRoot:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] EpochTransactionsRoot:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] EpochReceiptsRoot:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] SubmittedAt:0 FinalizedAt:0 Finalized:false Challenging:false Challenged:false}}"
DEBUG[06-15|00:43:15.876|rpc/handler.go:302]                 Served eth_getBalance                    reqid=22 t=42.086µs
DEBUG[06-15|00:43:15.876|rpc/handler.go:302]                 Served eth_getBalance                    reqid=23 t=34.648µs
DEBUG[06-15|00:43:15.876|rpc/handler.go:302]                 Served eth_getBalance                    reqid=24 t=36.946µs
DEBUG[06-15|00:43:15.877|rpc/handler.go:302]                 Served eth_getBalance                    reqid=25 t=33.082µs
INFO [06-15|00:43:16.020|tx/manager.go:779]                  New root chain block mined               number=597 numTxs=0 gasUsed=0      gasLimit=100000000
DEBUG[06-15|00:43:16.024|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(3: [3-4])"
    TestInvalidExit: rootchain_manager_test.go:958: Failed to check ETH balance(1)       : Expected 20.0 (after) == 0.0 (before) + 10.0 (diff), but it isn't
INFO [06-15|00:43:16.882|miner/unconfirmed.go:85]            🔨 mined potential block                  number=6   hash=1d80e3…bb9d0c
DEBUG[06-15|00:43:16.882|rpc/server.go:123]                  RPC server shutting down
INFO [06-15|00:43:16.882|core/blockchain.go:911]             Writing cached state to disk             block=6 hash=1d80e3…bb9d0c root=2155ba…070878
INFO [06-15|00:43:16.883|trie/database.go:748]               Persisted trie from memory database      nodes=19 size=5.92KiB   time=232.322µs gcnodes=0 gcsize=0.00B gctime=0s livenodes=24 livesize=3.77KiB
INFO [06-15|00:43:16.883|core/blockchain.go:911]             Writing cached state to disk             block=5 hash=443163…0ad8f1 root=7ebdd5…825212
INFO [06-15|00:43:16.883|trie/database.go:748]               Persisted trie from memory database      nodes=10 size=1.56KiB   time=71.907µs  gcnodes=0 gcsize=0.00B gctime=0s livenodes=14 livesize=2.21KiB
DEBUG[06-15|00:43:16.883|trie/database.go:526]               Dereferenced trie from memory database   nodes=3  size=595.00B   time=3.787µs   gcnodes=3 gcsize=595.00B gctime=3.516µs livenodes=11 livesize=1.63KiB
DEBUG[06-15|00:43:16.884|trie/database.go:526]               Dereferenced trie from memory database   nodes=3  size=595.00B   time=4.294µs   gcnodes=6 gcsize=1.16KiB gctime=7.544µs livenodes=8  livesize=1.05KiB
DEBUG[06-15|00:43:16.884|trie/database.go:526]               Dereferenced trie from memory database   nodes=3  size=595.00B   time=4.169µs   gcnodes=9 gcsize=1.74KiB gctime=11.44µs livenodes=5  livesize=479.00B
DEBUG[06-15|00:43:16.884|trie/database.go:526]               Dereferenced trie from memory database   nodes=4  size=677.00B   time=5.263µs   gcnodes=13 gcsize=2.40KiB gctime=16.439µs livenodes=1  livesize=-198.00B
DEBUG[06-15|00:43:16.884|trie/database.go:526]               Dereferenced trie from memory database   nodes=0  size=0.00B     time=1.255µs   gcnodes=13 gcsize=2.40KiB gctime=17.432µs livenodes=1  livesize=-198.00B
DEBUG[06-15|00:43:16.884|trie/database.go:526]               Dereferenced trie from memory database   nodes=0  size=0.00B     time=1.227µs   gcnodes=13 gcsize=2.40KiB gctime=18.403µs livenodes=1  livesize=-198.00B
INFO [06-15|00:43:16.885|core/blockchain.go:924]             Blockchain manager stopped
INFO [06-15|00:43:16.885|pls/handler.go:265]                 Stopping Plasma protocol
INFO [06-15|00:43:16.885|pls/handler.go:286]                 Plasma protocol stopped
INFO [06-15|00:43:16.885|core/tx_pool.go:425]                Transaction pool stopped
DEBUG[06-15|00:43:16.885|rpc/client.go:555]                  RPC connection read error                err=EOF
DEBUG[06-15|00:43:16.885|pls/downloader/downloader.go:578]   Reset ancient limit to zero
ERROR[06-15|00:43:16.922|tx/manager.go:795]                  New block event unsubscribed             err=nil
ERROR[06-15|00:43:16.947|tx/manager.go:747]                  Failed to re-subscribe root chian new block event err="client is closed"
INFO [06-15|00:43:16.923|tx/manager.go:513]                  TransactionManager stopped
--- FAIL: TestInvalidExit (172.88s)
FAIL
FAIL    github.com/Onther-Tech/plasma-evm/pls   172.910s
FAIL