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.

Sign up for GitHub

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

Jump to bottom

TestBasic/TestInvalidExit failure case(request transaction in NRE) #136

Open
modagi opened this issue Jun 15, 2020 · 0 comments
Open

TestBasic/TestInvalidExit failure case(request transaction in NRE) #136

modagi opened this issue Jun 15, 2020 · 0 comments
Assignees
@modagi
Labels
bug Something isn't working

Comments

@modagi
Copy link
Contributor

modagi commented Jun 15, 2020

TestBasic/TestInvalidExit in pla sometimes failed. NRE must occur after ORE in the tests, but the test fails because it contains a request transaction.

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: 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 TestBasic/TestInvalidExit in pls

Actual behaviour

Sometimes fail

Steps to reproduce the behaviour

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

Backtrace

...
INFO [06-14|21:46:32.008|miner/unconfirmed.go:107]           🔗 block reached canonical chain          number=12     hash=c24ec5…7be547
INFO [06-14|21:46:32.008|miner/unconfirmed.go:85]            🔨 mined potential block                  number=19     hash=fdc46e…2c17e9
INFO [06-14|21:46:32.009|miner/worker.go:1177]               Commit new mining work                   number=20     sealhash=b21ec7…ccffa7 uncles=0 txs=0 gas=0      fees=0           elapsed=308.586µs
DEBUG[06-14|21:46:32.009|core/tx_pool.go:1254]               Reinjecting stale transactions           count=0
INFO [06-14|21:46:32.009|pls/rootchain_manager.go:424]       New block is mined                       number=19
DEBUG[06-14|21:46:32.010|rpc/handler.go:302]                 Served eth_getTransactionReceipt         reqid=65 t=1.758675ms
WARN [06-14|21:46:32.010|pls/rootchain_manager_test.go:2555] Check Block Number                       expectedBlockNumber=19 minedBlockNumber=19 forkNumber=1
WARN [06-14|21:46:32.010|pls/rootchain_manager_test.go:2633] Check epoch after submission             expectedEpochNumber=15
INFO [06-14|21:46:32.012|tx/manager.go:779]                  New root chain block mined               number=151212 numTxs=0 gasUsed=0      gasLimit=100000000
ERROR[06-14|21:46:32.012|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-14|21:46:32.012|pls/rootchain_manager.go:437]       Operator account balance on rootchain is too low
DEBUG[06-14|21:46:32.012|pls/rootchain_manager.go:452]       Read blocks for NRE                      epochNumber=15 numBlocks=2 elapsed=2.395µs
DEBUG[06-14|21:46:32.014|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(13: [16-17])"
DEBUG[06-14|21:46:32.015|tx/manager.go:815]                  Inspect queue                            addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 total=10 confirmed=9 unconfiemd=1 pending=0
INFO [06-14|21:46:32.015|tx/manager.go:234]                  Raw transaction added                    caption="submitNRE(15: [18-19])" from=0xb79749F25Ef64F9AC277A4705887101D3311A0F4
DEBUG[06-14|21:46:32.058|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(13: [16-17])"
WARN [06-14|21:46:32.060|tx/manager.go:396]                  Account nonce has increased by another transaction previousNonce=638 currentNonce=639
INFO [06-14|21:46:32.062|tx/manager.go:347]                  Transaction sent                         hash=fe0b1d…83e2ac nonce=639 caption="submitNRE(15: [18-19])" gasprice=1000000000
WARN [06-14|21:46:32.063|tx/manager.go:494]                  Ethereum Transaction not found. It may be pending err="not found"  caption="submitNRE(15: [18-19])" hash=0xfe0b1d2623815b4c42ee014b2d67d686820315f256d657da3ed260cf6b83e2ac
INFO [06-14|21:46:32.063|tx/manager.go:565]                  Gas price adjusted                       caption="submitNRE(15: [18-19])" decrease=false previous="1 Gwei"           adjusted="1.19921875 Gwei"
INFO [06-14|21:46:32.065|tx/manager.go:347]                  Transaction sent                         hash=1e3a3d…c4d1ad nonce=639 caption="submitNRE(15: [18-19])" gasprice=1200000000
INFO [06-14|21:46:33.010|tx/manager.go:779]                  New root chain block mined               number=151213 numTxs=0 gasUsed=0      gasLimit=100000000
DEBUG[06-14|21:46:33.011|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(13: [16-17])"
DEBUG[06-14|21:46:33.953|core/tx_pool.go:379]                Transaction pool status report           executable=0 queued=0 stales=0
INFO [06-14|21:46:34.002|pls/rootchain_manager.go:533]       RootChain epoch prepared                 epochNumber=16 startBlockNumber=20 endBlockNumber=20 epochLength=1 isRequest=true  userActivated=false isEmpty=false ForkNumber=0 isRebase=false
INFO [06-14|21:46:34.002|miner/miner.go:178]                 ORB epoch is prepared, ORB epoch is started epochLength=1
INFO [06-14|21:46:34.003|pls/rootchain_manager_test.go:2641] Next prepared epoch                      e="&{ForkNumber:+0 EpochNumber:+16 StartBlockNumber:+20 EndBlockNumber:+20 RequestStart:+6 RequestEnd:+6 EpochIsEmpty:false IsRequest:true UserActivated:false Rebase:false Raw:{Address:[76 244 8 242 68 50 47 236 223 40 186 34 23 214 43 12 41 65 166 160] 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 16 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 20 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 20 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 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 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 1 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:151214 TxHash:[30 58 61 177 61 194 24 198 26 213 94 228 68 111 248 73 79 101 233 124 21 164 140 193 3 233 1 244 189 196 209 173] TxIndex:0 BlockHash:[109 5 117 58 210 242 30 111 51 48 37 40 206 119 139 202 150 151 227 87 65 71 242 37 64 183 114 20 183 215 126 92] Index:1 Removed:false}}"
WARN [06-14|21:46:34.007|pls/rootchain_manager_test.go:2652] Epoch?                                   e="{StartBlockNumber:18 EndBlockNumber:19 Timestamp:1592171172 IsEmpty:false Initialized:true IsRequest:false UserActivated:false Rebase:false RE:{RequestStart:0 RequestEnd:0 FirstRequestBlockId:0 NumEnter:0 NextEnterEpoch:0 NextEpoch:0} NRE:{EpochStateRoot:[210 149 108 7 80 237 124 215 193 28 121 121 167 169 23 215 158 241 135 138 70 103 16 79 92 123 229 96 173 147 166 193] EpochTransactionsRoot:[169 240 182 249 58 214 183 198 130 75 98 191 42 79 235 25 82 59 141 232 12 243 244 10 16 85 239 84 142 102 132 201] EpochReceiptsRoot:[166 41 201 135 49 55 146 231 78 143 209 46 203 121 141 142 167 216 224 235 31 55 230 115 3 18 197 198 242 253 218 24] SubmittedAt:1592171194 FinalizedAt:0 Finalized:false Challenging:false Challenged:false}}"
WARN [06-14|21:46:34.007|pls/rootchain_manager_test.go:2532] Check mined block                        expectedBlockNumber=20
INFO [06-14|21:46:34.008|tx/manager.go:779]                  New root chain block mined               number=151214 numTxs=1 gasUsed=268779 gasLimit=100000000
DEBUG[06-14|21:46:34.008|pls/rootchain_manager.go:569]       rcm.getEpoch                             epoch="{StartBlockNumber:20 EndBlockNumber:20 Timestamp:1592171194 IsEmpty:false Initialized:true IsRequest:true UserActivated:false Rebase:false RE:{RequestStart:6 RequestEnd:6 FirstRequestBlockId:3 NumEnter:0 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-14|21:46:34.008|pls/rootchain_manager.go:574]       Num Orbs                                 epochNumber=16 numORBs=1 requestBlockId=3 e.EndBlockNumber=20 e.StartBlockNumber=20
DEBUG[06-14|21:46:34.010|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(13: [16-17])"
DEBUG[06-14|21:46:34.010|pls/rootchain_manager.go:584]       Fetching ORB                             blockNumber=20     requestStart=6 requestEnd=6 requestBlockId=3
DEBUG[06-14|21:46:34.012|pls/rootchain_manager.go:594]       Request fetched                          requestId=6 hash=23afa563ab243d4426cf695d4e36b645e139fc953bd05116587a6a858e210fa7 request="{Timestamp:1592171162 IsExit:true IsTransfer:false Finalized:false Challenged:false Value:+0 Requestor:[81 91 56 91 220 137 188 194 144 119 242 176 10 136 98 40 131 191 180 152] To:[0 123 22 61 15 112 151 123 228 114 24 61 229 48 60 19 41 179 165 68] TrieKey:[156 77 241 216 71 138 188 52 93 158 222 46 67 134 198 58 241 51 97 82 25 65 48 232 241 208 79 103 47 153 178 95] Hash:[35 175 165 99 171 36 61 68 38 207 105 93 78 54 182 69 225 57 252 149 59 208 81 22 88 122 106 133 142 33 15 167] TrieValue:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 3 120 45 172 233 217 0 0]}"
DEBUG[06-14|21:46:34.013|pls/rootchain_manager.go:619]       Request tx.data                          payload=141ecf4600000000000000000000000000000000000000000000000000000000000000010000000000000000000000000000000000000000000000000000000000000006000000000000000000000000515b385bdc89bcc29077f2b00a88622883bfb4989c4df1d8478abc345d9ede2e4386c63af1336152194130e8f1d04f672f99b25f00000000000000000000000000000000000000000000000000000000000000a0000000000000000000000000000000000000000000000000000000000000002000000000000000000000000000000000000000000000000003782dace9d90000
DEBUG[06-14|21:46:34.013|pls/rootchain_manager.go:626]       Request Transaction                      tx="&{data:{AccountNonce:0 Price:0xc021c72640 GasLimit:100000 Recipient:0xc021c39d20 Amount:0xc021c72620 Payload:[20 30 207 70 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 1 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 81 91 56 91 220 137 188 194 144 119 242 176 10 136 98 40 131 191 180 152 156 77 241 216 71 138 188 52 93 158 222 46 67 134 198 58 241 51 97 82 25 65 48 232 241 208 79 103 47 153 178 95 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 160 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 32 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 3 120 45 172 233 217 0 0] V:0xc021c72660 R:0xc021c72680 S:0xc021c726a0 Hash:<nil>} hash:{v:[35 175 165 99 171 36 61 68 38 207 105 93 78 54 182 69 225 57 252 149 59 208 81 22 88 122 106 133 142 33 15 167]} size:{v:<nil>} from:{v:<nil>}}"
INFO [06-14|21:46:34.013|pls/rootchain_manager.go:632]       Request txs fetched                      blockNumber=20     requestBlockId=3 numRequests=1 elapsed=4.90567ms
INFO [06-14|21:46:34.013|pls/rootchain_manager.go:654]       Waiting new request block mined event...
INFO [06-14|21:46:34.058|tx/manager.go:593]                  Transaction is mined                     nonce=639 caption="submitNRE(15: [18-19])" reverted=false from=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 hash=0x1e3a3db13dc218c61ad55ee4446ff8494f65e97c15a48cc103e901f4bdc4d1ad
INFO [06-14|21:46:34.059|tx/manager.go:565]                  Gas price adjusted                       caption="submitNRE(15: [18-19])" decrease=true  previous="1.19921875 Gwei"  adjusted="1 Gwei"
DEBUG[06-14|21:46:34.061|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(13: [16-17])"
INFO [06-14|21:46:35.010|tx/manager.go:779]                  New root chain block mined               number=151215 numTxs=0 gasUsed=0      gasLimit=100000000
DEBUG[06-14|21:46:35.012|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(13: [16-17])"
INFO [06-14|21:46:36.014|tx/manager.go:779]                  New root chain block mined               number=151216 numTxs=0 gasUsed=0      gasLimit=100000000
DEBUG[06-14|21:46:36.016|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(13: [16-17])"
DEBUG[06-14|21:46:36.058|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(13: [16-17])"
INFO [06-14|21:46:37.008|tx/manager.go:779]                  New root chain block mined               number=151217 numTxs=0 gasUsed=0      gasLimit=100000000
DEBUG[06-14|21:46:37.011|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(13: [16-17])"
INFO [06-14|21:46:38.004|tx/manager.go:779]                  New root chain block mined               number=151218 numTxs=0 gasUsed=0      gasLimit=100000000
DEBUG[06-14|21:46:38.004|tx/manager.go:815]                  Inspect queue                            addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 total=11 confirmed=9 unconfiemd=2 pending=0
DEBUG[06-14|21:46:38.007|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(13: [16-17])"
DEBUG[06-14|21:46:38.059|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(13: [16-17])"
INFO [06-14|21:46:39.008|tx/manager.go:779]                  New root chain block mined               number=151219 numTxs=0 gasUsed=0      gasLimit=100000000
DEBUG[06-14|21:46:39.010|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(13: [16-17])"
INFO [06-14|21:46:40.011|tx/manager.go:779]                  New root chain block mined               number=151220 numTxs=0 gasUsed=0      gasLimit=100000000
DEBUG[06-14|21:46:40.013|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(13: [16-17])"
DEBUG[06-14|21:46:40.058|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(13: [16-17])"
INFO [06-14|21:46:41.010|tx/manager.go:779]                  New root chain block mined               number=151221 numTxs=0 gasUsed=0      gasLimit=100000000
DEBUG[06-14|21:46:41.012|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(13: [16-17])"
INFO [06-14|21:46:42.008|tx/manager.go:779]                  New root chain block mined               number=151222 numTxs=0 gasUsed=0      gasLimit=100000000
DEBUG[06-14|21:46:42.012|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(13: [16-17])"
DEBUG[06-14|21:46:42.058|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(13: [16-17])"
INFO [06-14|21:46:43.004|tx/manager.go:779]                  New root chain block mined               number=151223 numTxs=0 gasUsed=0      gasLimit=100000000
DEBUG[06-14|21:46:43.006|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(13: [16-17])"
DEBUG[06-14|21:46:44.016|miner/worker.go:925]                Request tx to mine                       rtx="&{data:{AccountNonce:0 Price:0xc021c72640 GasLimit:100000 Recipient:0xc021c39d20 Amount:0xc021c72620 Payload:[20 30 207 70 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 1 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 81 91 56 91 220 137 188 194 144 119 242 176 10 136 98 40 131 191 180 152 156 77 241 216 71 138 188 52 93 158 222 46 67 134 198 58 241 51 97 82 25 65 48 232 241 208 79 103 47 153 178 95 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 160 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 32 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 3 120 45 172 233 217 0 0] V:0xc021c72660 R:0xc021c72680 S:0xc021c726a0 Hash:<nil>} hash:{v:[35 175 165 99 171 36 61 68 38 207 105 93 78 54 182 69 225 57 252 149 59 208 81 22 88 122 106 133 142 33 15 167]} size:{v:<nil>} from:{v:{signer:{chainId:0xc00000f060 chainIdMul:0xc00067e1e0} from:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]}}}" hash=0x23afa563ab243d4426cf695d4e36b645e139fc953bd05116587a6a858e210fa7
INFO [06-14|21:46:44.019|miner/worker.go:1177]               Commit new mining work                   number=20     sealhash=a45c87…f058ed uncles=0 txs=1 gas=55177  fees=5.5177e-05  elapsed=4.659ms
INFO [06-14|21:46:44.020|miner/worker.go:635]                Successfully sealed new block            number=20     sealhash=a45c87…f058ed hash=6b7d11…ed0817 elapsed=1.285ms
DEBUG[06-14|21:46:44.020|core/tx_pool.go:1254]               Reinjecting stale transactions           count=0
INFO [06-14|21:46:44.021|tx/manager.go:779]                  New root chain block mined               number=151224 numTxs=0 gasUsed=0      gasLimit=100000000
DEBUG[06-14|21:46:44.023|tx/manager.go:815]                  Inspect queue                            addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 total=11 confirmed=9 unconfiemd=2 pending=0
DEBUG[06-14|21:46:44.029|miner/worker.go:925]                Request tx to mine                       rtx="&{data:{AccountNonce:0 Price:0xc021c72640 GasLimit:100000 Recipient:0xc021c39d20 Amount:0xc021c72620 Payload:[20 30 207 70 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 1 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 81 91 56 91 220 137 188 194 144 119 242 176 10 136 98 40 131 191 180 152 156 77 241 216 71 138 188 52 93 158 222 46 67 134 198 58 241 51 97 82 25 65 48 232 241 208 79 103 47 153 178 95 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 160 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 32 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 3 120 45 172 233 217 0 0] V:0xc021c72660 R:0xc021c72680 S:0xc021c726a0 Hash:<nil>} hash:{v:[35 175 165 99 171 36 61 68 38 207 105 93 78 54 182 69 225 57 252 149 59 208 81 22 88 122 106 133 142 33 15 167]} size:{v:<nil>} from:{v:{signer:{chainId:0xc00000f060 chainIdMul:0xc00067e1e0} from:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]}}}" hash=0x23afa563ab243d4426cf695d4e36b645e139fc953bd05116587a6a858e210fa7
DEBUG[06-14|21:46:44.030|core/state_transition.go:309]       VM returned with error                   err="evm: execution reverted"
INFO [06-14|21:46:44.030|miner/unconfirmed.go:107]           🔗 block reached canonical chain          number=13     hash=18fea6…2a500e
INFO [06-14|21:46:44.030|miner/worker.go:1177]               Commit new mining work                   number=21     sealhash=c0533e…848c82 uncles=0 txs=1 gas=24054  fees=2.4054e-05  elapsed=8.725ms
INFO [06-14|21:46:44.031|miner/unconfirmed.go:85]            🔨 mined potential block                  number=20     hash=6b7d11…ed0817
INFO [06-14|21:46:44.031|miner/worker.go:635]                Successfully sealed new block            number=21     sealhash=c0533e…848c82 hash=d90ee0…a4b496 elapsed=877.419µs
INFO [06-14|21:46:44.032|miner/worker.go:1081]               Mining too far in the future             wait=2s
INFO [06-14|21:46:44.032|pls/rootchain_manager.go:424]       New block is mined                       number=20
DEBUG[06-14|21:46:44.032|rpc/handler.go:302]                 Served eth_getTransactionReceipt         reqid=66 t=96.048µs
INFO [06-14|21:46:44.033|pls/rootchain_manager.go:659]       New request block is mined               blockNumber=20     txs=1
DEBUG[06-14|21:46:44.033|core/tx_pool.go:1254]               Reinjecting stale transactions           count=0
WARN [06-14|21:46:44.033|pls/rootchain_manager_test.go:2555] Check Block Number                       expectedBlockNumber=20 minedBlockNumber=20 forkNumber=1
WARN [06-14|21:46:44.033|pls/rootchain_manager_test.go:2581] Check mined block                        expectedBlockNumber=20
DEBUG[06-14|21:46:44.033|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(13: [16-17])"
ERROR[06-14|21:46:44.034|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-14|21:46:44.035|pls/rootchain_manager.go:437]       Operator account balance on rootchain is too low
INFO [06-14|21:46:44.035|tx/manager.go:686]                  Transaction is confirmed                 addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(13: [16-17])"
DEBUG[06-14|21:46:44.035|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(15: [18-19])"
DEBUG[06-14|21:46:44.037|tx/manager.go:815]                  Inspect queue                            addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 total=11 confirmed=10 unconfiemd=1 pending=0
INFO [06-14|21:46:44.037|tx/manager.go:234]                  Raw transaction added                    caption=submitORB(20)            from=0xb79749F25Ef64F9AC277A4705887101D3311A0F4
INFO [06-14|21:46:44.037|pls/rootchain_manager.go:424]       New block is mined                       number=21
ERROR[06-14|21:46:44.038|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-14|21:46:44.038|pls/rootchain_manager.go:437]       Operator account balance on rootchain is too low
DEBUG[06-14|21:46:44.038|tx/manager.go:815]                  Inspect queue                            addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 total=12 confirmed=10 unconfiemd=1 pending=1
INFO [06-14|21:46:44.038|tx/manager.go:234]                  Raw transaction added                    caption=submitORB(21)            from=0xb79749F25Ef64F9AC277A4705887101D3311A0F4
INFO [06-14|21:46:44.040|pls/rootchain_manager.go:690]       RootChain block finalized                forkNumber=0 blockNubmer=15
INFO [06-14|21:46:44.041|pls/rootchain_manager.go:800]       Invalid Exit Detected                    invalidExit="&{forkNumber:0xc021e99ae0 blockNumber:0xc021e99b00 receipt:0xc021e88700 index:0 proof:[]}" forkNumber=0 blockNumber=21
DEBUG[06-14|21:46:44.058|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(15: [18-19])"
WARN [06-14|21:46:44.062|tx/manager.go:396]                  Account nonce has increased by another transaction previousNonce=639 currentNonce=640
INFO [06-14|21:46:44.063|tx/manager.go:347]                  Transaction sent                         hash=ba49de…db0289 nonce=640 caption=submitORB(20)            gasprice=1000000000
WARN [06-14|21:46:44.065|tx/manager.go:494]                  Ethereum Transaction not found. It may be pending err="not found"               caption=submitORB(20)            hash=0xba49de77dd8929fdb197fc1e1ca33d9284218d27f9d6318012be09b73cdb0289
INFO [06-14|21:46:44.065|tx/manager.go:565]                  Gas price adjusted                       caption=submitORB(20)            decrease=false previous="1 Gwei"           adjusted="1.19921875 Gwei"
INFO [06-14|21:46:44.066|tx/manager.go:347]                  Transaction sent                         hash=8aca3b…a501ce nonce=640 caption=submitORB(20)            gasprice=1200000000
INFO [06-14|21:46:45.005|tx/manager.go:779]                  New root chain block mined               number=151225 numTxs=0 gasUsed=0      gasLimit=100000000
DEBUG[06-14|21:46:45.008|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(15: [18-19])"
WARN [06-14|21:46:46.007|pls/rootchain_manager_test.go:2595] Check Submitted Block Number             expectedBlockNumber=20 minedBlockNumber=20 forkNumber=1
INFO [06-14|21:46:46.007|pls/rootchain_manager.go:533]       RootChain epoch prepared                 epochNumber=17 startBlockNumber=21 endBlockNumber=22 epochLength=2 isRequest=false userActivated=false isEmpty=false ForkNumber=0 isRebase=false
INFO [06-14|21:46:46.010|tx/manager.go:779]                  New root chain block mined               number=151226 numTxs=1 gasUsed=214254 gasLimit=100000000
DEBUG[06-14|21:46:46.012|tx/manager.go:680]                  check raw is confirmed                   addr=0xb79749F25Ef64F9AC277A4705887101D3311A0F4 caption="submitNRE(15: [18-19])"
WARN [06-14|21:46:46.012|pls/rootchain_manager_test.go:2633] Check epoch after submission             expectedEpochNumber=16
INFO [06-14|21:46:46.012|pls/rootchain_manager_test.go:2641] Next prepared epoch                      e="&{ForkNumber:+0 EpochNumber:+17 StartBlockNumber:+21 EndBlockNumber:+22 RequestStart:+0 RequestEnd:+0 EpochIsEmpty:false IsRequest:false UserActivated:false Rebase:false Raw:{Address:[76 244 8 242 68 50 47 236 223 40 186 34 23 214 43 12 41 65 166 160] 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 17 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 21 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 22 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:151226 TxHash:[138 202 59 227 249 160 54 13 50 220 140 85 250 83 121 41 50 55 193 69 102 218 115 234 0 240 18 152 151 165 1 206] TxIndex:0 BlockHash:[199 119 120 187 169 103 103 236 234 208 27 67 78 72 3 91 42 242 5 70 195 180 181 60 121 201 232 9 235 39 108 112] Index:2 Removed:false}}"
WARN [06-14|21:46:46.014|pls/rootchain_manager_test.go:2652] Epoch?                                   e="{StartBlockNumber:20 EndBlockNumber:20 Timestamp:1592171194 IsEmpty:false Initialized:true IsRequest:true UserActivated:false Rebase:false RE:{RequestStart:6 RequestEnd:6 FirstRequestBlockId:3 NumEnter:0 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-14|21:46:46.015|internal/plsapi/api.go:761]         Executing EVM call finished              runtime=362.676µs
DEBUG[06-14|21:46:46.015|rpc/handler.go:302]                 Served eth_call                          reqid=67 t=503.906µs
DEBUG[06-14|21:46:46.015|internal/plsapi/api.go:761]         Executing EVM call finished              runtime=140.546µs
DEBUG[06-14|21:46:46.015|rpc/handler.go:302]                 Served eth_call                          reqid=68 t=268.228µs
DEBUG[06-14|21:46:46.016|internal/plsapi/api.go:761]         Executing EVM call finished              runtime=130.183µs
DEBUG[06-14|21:46:46.016|rpc/handler.go:302]                 Served eth_call                          reqid=69 t=260.484µs
DEBUG[06-14|21:46:46.016|internal/plsapi/api.go:761]         Executing EVM call finished              runtime=134.637µs
DEBUG[06-14|21:46:46.016|rpc/handler.go:302]                 Served eth_call                          reqid=70 t=274.154µs
DEBUG[06-14|21:46:46.017|pls/rootchain_manager_test.go:2522] Sample transaction is submitted in child chian
WARN [06-14|21:46:46.017|pls/rootchain_manager_test.go:2532] Check mined block                        expectedBlockNumber=21
DEBUG[06-14|21:46:46.018|rpc/handler.go:302]                 Served eth_getTransactionReceipt         reqid=71 t=175.589µs
INFO [06-14|21:46:46.018|miner/unconfirmed.go:107]           🔗 block reached canonical chain          number=14     hash=2d763c…dd7413
INFO [06-14|21:46:46.018|miner/unconfirmed.go:85]            🔨 mined potential block                  number=21     hash=d90ee0…a4b496
WARN [06-14|21:46:46.019|pls/rootchain_manager_test.go:2555] Check Block Number                       expectedBlockNumber=21 minedBlockNumber=21 forkNumber=1
    TestBasic: rootchain_manager_test.go:658: Expected isRequest: false, Actual isRequest true
DEBUG[06-14|21:46:46.020|rpc/server.go:123]                  RPC server shutting down
INFO [06-14|21:46:46.020|core/blockchain.go:911]             Writing cached state to disk             block=21 hash=d90ee0…a4b496 root=ec9e32…af19cd
INFO [06-14|21:46:46.020|trie/database.go:748]               Persisted trie from memory database      nodes=24 size=6.40KiB   time=182.964µs gcnodes=0 gcsize=0.00B gctime=0s livenodes=80 livesize=14.68KiB
INFO [06-14|21:46:46.020|core/blockchain.go:911]             Writing cached state to disk             block=20 hash=6b7d11…ed0817 root=3adeeb…f09142
INFO [06-14|21:46:46.021|trie/database.go:748]               Persisted trie from memory database      nodes=3  size=634.00B   time=25.372µs  gcnodes=0 gcsize=0.00B gctime=0s livenodes=77 livesize=14.07KiB
DEBUG[06-14|21:46:46.021|trie/database.go:526]               Dereferenced trie from memory database   nodes=3  size=595.00B   time=4.119µs   gcnodes=3 gcsize=595.00B gctime=3.847µs livenodes=74 livesize=13.48KiB
DEBUG[06-14|21:46:46.021|trie/database.go:526]               Dereferenced trie from memory database   nodes=3  size=595.00B   time=3.815µs   gcnodes=6 gcsize=1.16KiB gctime=7.396µs livenodes=71 livesize=12.90KiB
DEBUG[06-14|21:46:46.021|trie/database.go:526]               Dereferenced trie from memory database   nodes=3  size=595.00B   time=3.636µs   gcnodes=9 gcsize=1.74KiB gctime=10.782µs livenodes=68 livesize=12.32KiB
DEBUG[06-14|21:46:46.021|trie/database.go:526]               Dereferenced trie from memory database   nodes=4  size=677.00B   time=5.501µs   gcnodes=13 gcsize=2.40KiB gctime=16.014µs livenodes=64 livesize=11.66KiB
DEBUG[06-14|21:46:46.021|trie/database.go:526]               Dereferenced trie from memory database   nodes=3  size=659.00B   time=4.13µs    gcnodes=16 gcsize=3.05KiB gctime=19.891µs livenodes=61 livesize=11.02KiB
DEBUG[06-14|21:46:46.022|trie/database.go:526]               Dereferenced trie from memory database   nodes=3  size=659.00B   time=4.1µs     gcnodes=19 gcsize=3.69KiB gctime=23.724µs livenodes=58 livesize=10.37KiB
DEBUG[06-14|21:46:46.022|trie/database.go:526]               Dereferenced trie from memory database   nodes=5  size=863.00B   time=19.569µs  gcnodes=24 gcsize=4.53KiB gctime=43.032µs livenodes=53 livesize=9.53KiB
DEBUG[06-14|21:46:46.022|trie/database.go:526]               Dereferenced trie from memory database   nodes=8  size=1.28KiB   time=20.605µs  gcnodes=32 gcsize=5.82KiB gctime=63.375µs livenodes=45 livesize=8.25KiB
DEBUG[06-14|21:46:46.022|trie/database.go:526]               Dereferenced trie from memory database   nodes=8  size=1.32KiB   time=21.641µs  gcnodes=40 gcsize=7.13KiB gctime=84.756µs livenodes=37 livesize=6.93KiB
DEBUG[06-14|21:46:46.022|trie/database.go:526]               Dereferenced trie from memory database   nodes=3  size=659.00B   time=17.038µs  gcnodes=43 gcsize=7.78KiB gctime=101.519µs livenodes=34 livesize=6.29KiB
DEBUG[06-14|21:46:46.022|trie/database.go:526]               Dereferenced trie from memory database   nodes=3  size=659.00B   time=3.902µs   gcnodes=46 gcsize=8.42KiB gctime=105.164µs livenodes=31 livesize=5.64KiB
DEBUG[06-14|21:46:46.023|trie/database.go:526]               Dereferenced trie from memory database   nodes=3  size=659.00B   time=4.188µs   gcnodes=49 gcsize=9.06KiB gctime=109.088µs livenodes=28 livesize=5.00KiB
DEBUG[06-14|21:46:46.023|trie/database.go:526]               Dereferenced trie from memory database   nodes=3  size=659.00B   time=18.507µs  gcnodes=52 gcsize=9.71KiB gctime=127.327µs livenodes=25 livesize=4.36KiB
DEBUG[06-14|21:46:46.023|trie/database.go:526]               Dereferenced trie from memory database   nodes=6  size=996.00B   time=6.762µs   gcnodes=58 gcsize=10.68KiB gctime=133.826µs livenodes=19 livesize=3.38KiB
DEBUG[06-14|21:46:46.023|trie/database.go:526]               Dereferenced trie from memory database   nodes=3  size=659.00B   time=17.314µs  gcnodes=61 gcsize=11.32KiB gctime=150.877µs livenodes=16 livesize=2.74KiB
DEBUG[06-14|21:46:46.023|trie/database.go:526]               Dereferenced trie from memory database   nodes=3  size=659.00B   time=4.097µs   gcnodes=64 gcsize=11.97KiB gctime=154.713µs livenodes=13 livesize=2.10KiB
DEBUG[06-14|21:46:46.023|trie/database.go:526]               Dereferenced trie from memory database   nodes=3  size=659.00B   time=4.334µs   gcnodes=67 gcsize=12.61KiB gctime=158.783µs livenodes=10 livesize=1.45KiB
DEBUG[06-14|21:46:46.024|trie/database.go:526]               Dereferenced trie from memory database   nodes=3  size=659.00B   time=4.515µs   gcnodes=70 gcsize=13.25KiB gctime=163.043µs livenodes=7  livesize=830.00B
DEBUG[06-14|21:46:46.024|trie/database.go:526]               Dereferenced trie from memory database   nodes=6  size=1.00KiB   time=6.988µs   gcnodes=76 gcsize=14.26KiB gctime=169.761µs livenodes=1  livesize=-198.00B
DEBUG[06-14|21:46:46.021|rpc/client.go:555]                  RPC connection read error                err=EOF
DEBUG[06-14|21:46:46.024|trie/database.go:526]               Dereferenced trie from memory database   nodes=0  size=0.00B     time=1.176µs   gcnodes=76 gcsize=14.26KiB gctime=170.69µs  livenodes=1  livesize=-198.00B
DEBUG[06-14|21:46:46.024|trie/database.go:526]               Dereferenced trie from memory database   nodes=0  size=0.00B     time=1.158µs   gcnodes=76 gcsize=14.26KiB gctime=171.595µs livenodes=1  livesize=-198.00B
INFO [06-14|21:46:46.024|core/blockchain.go:924]             Blockchain manager stopped
INFO [06-14|21:46:46.025|pls/handler.go:265]                 Stopping Plasma protocol
INFO [06-14|21:46:46.025|pls/handler.go:286]                 Plasma protocol stopped
INFO [06-14|21:46:46.025|core/tx_pool.go:425]                Transaction pool stopped
INFO [06-14|21:46:46.025|tx/manager.go:513]                  TransactionManager stopped
DEBUG[06-14|21:46:46.025|pls/downloader/downloader.go:578]   Reset ancient limit to zero
ERROR[06-14|21:46:46.048|tx/manager.go:795]                  New block event unsubscribed             err=nil
ERROR[06-14|21:46:46.074|tx/manager.go:747]                  Failed to re-subscribe root chian new block event err="client is closed"
--- FAIL: TestBasic (303.20s)
@modagi modagi added the bug Something isn't working label Jun 15, 2020
@modagi modagi self-assigned this Jun 15, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@modagi modagi

Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@modagi