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.

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

Kill the besu service when we deploy the smart contract by below function call #3102

Closed
eu09 opened this issue Nov 24, 2021 · 16 comments
Closed
Assignees
Labels
bug Something isn't working P3 Medium (ex: JSON-RPC request not working with a specific client library due to loose spec assumtion) TeamRevenant GH issues worked on by Revenant Team

Comments

@eu09
Copy link

eu09 commented Nov 24, 2021

Please suggest us how to deal with a issue , when our developer who write a smart contract included below function call , when it deploy it will kill the besu service

result := delegatecall(gas(), _impl, ptr, calldatasize(), 0, 0)
size := returndatasize()
returndatacopy(ptr, 0, size)

.....
emit TopUpPaymentWalletFailed(paymentWalletAddr, gasUsed, currBalance, ptr);

Versions (Add all that apply)

  • Software version: [besu --21.10.2]
  • OS Name & Version: [ubuntu 20.04 lts x64]
  • Kernel Version: [Linux ip-172-31-24-141 5.11.0-1021-aws #22~20.04.2-Ubuntu SMP Wed Oct 27 21:27:13 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux]
  • Docker Version: [ Version: 20.10.5]
  • Cloud VM, type, size: [Amazon Web Services t3.2xlarge]

Genesis file

{
"config" : {
"chainId" : 2021,
"constantinoplefixblock" : 0,
"istanbulBlock" : 9702190,
"muirglacierBlock" : 9702195,
"berlinBlock" : 9702200,
"contractSizeLimit": 245760,
"ibft2" : {
"blockperiodseconds" : 2,
"epochlength" : 30000,
"requesttimeoutseconds" : 10,
"blockreward": "5000000000000000",
"miningbeneficiary": "0xe0275e0cf831d5a74089e1a66c810b57891c2d85"
}
},
"nonce" : "0x0",
"timestamp" : "0x58ee40ba",
"gasLimit" : "0x1fffffffffffff",
"difficulty" : "0x1",
"mixHash" : "0x63746963616c2062797a616e74696e65206661756c7420746f6c6572616e6365",
"coinbase" : "0x0000000000000000000000000000000000000000",

@MadelineMurray MadelineMurray added the bug Something isn't working label Nov 24, 2021
@eu09
Copy link
Author

eu09 commented Nov 29, 2021

We can reproduce the issue by these 2 contracts (note that comment in the 2nd contract is intended)

contract Contract {
    function callMe(address) external {
        revert("Revert anyway");
    }
}

contract OOM {
    event Reverted(address indexed addr, bytes revertReason);

    function callMe(address addr) external {
        bytes memory ptr;
        uint256 offset;
        uint256 size;
        uint256 result;

        assembly {
            ptr := mload(0x40)
            calldatacopy(ptr, 0, calldatasize())
            result := delegatecall(gas(), addr, ptr, calldatasize(), 0, 0)
            size := returndatasize()
            returndatacopy(ptr, 0, size)

            switch result
            case 0 {
                if gt(size, 0) {
                    offset := add(ptr, 0x120)
                    mstore(0x40, offset)
                    // ptr := add(ptr, 4)
                    // let lengthFieldLength := mload(ptr)
                    // ptr := add(ptr, lengthFieldLength)
                }
            }
        }

        if (result == 0) {
            emit Reverted(addr, ptr);
        }
    }
}

Make a transaction to OOM and delegatecall to Contract, CPU and memory usage rise, the node becomes unresponsive until we restart and produce below error message

"class":"PeerDiscoveryAgent","message":"P2P peer discovery agent started and listening on /0.0.0.0:30303","throwable":""}
today at 16:14 {"timestamp":"2021-11-19T08:14:30,397","container":"15590c1d9d97","level":"INFO","thread":"vert.x-eventloop-thread-4","class":"PeerDiscoveryAgent","message":"Writing node record to disk. NodeRecord{seq=55, publicKey=0x02579bab37e54dc4dcb996bc6bc80594e915062352584d3428e302de1981fdd66e, udpAddress=Optional[/172.16.239.14:30303], tcpAddress=Optional[/172.16.239.14:30303], asBase64=-Je4QBqVfk4CCun01TZMrbNKRzXDxaOQZL1ApB127RlL3MU3Iy2wKyZdtAVAtawaJWp0WF2Xo-l2zkXFXHrdug3p2Ho3g2V0aMfGhEV_Vf-AgmlkgnY0gmlwhKwQ7w6Jc2VjcDI1NmsxoQJXm6s35U3E3LmWvGvIBZTpFQYjUlhNNCjjAt4Zgf3WboN0Y3CCdl-DdWRwgnZf, nodeId=0x8550c1493dab8574daf645d0fc638101f646aef1fc921478bce1f35e9071bf7b, customFields={tcp=30303, udp=30303, ip=0xac10ef0e, eth=[[0x457f55ff, 0x]], id=V4, secp256k1=0x02579bab37e54dc4dcb996bc6bc80594e915062352584d3428e302de1981fdd66e}}","throwable":""}
today at 16:14 {"timestamp":"2021-11-19T08:14:30,470","container":"15590c1d9d97","level":"INFO","thread":"main","class":"DefaultP2PNetwork","message":"Enode URL enode://579bab37e54dc4dcb996bc6bc80594e915062352584d3428e302de1981fdd66ec991c82a594cd9279bed6da800d57ce2129e40efd1128074d10cebe83046ea6c@172.16.239.14:30303","throwable":""}
today at 16:14 {"timestamp":"2021-11-19T08:14:30,471","container":"15590c1d9d97","level":"INFO","thread":"main","class":"DefaultP2PNetwork","message":"Node address 0xfc638101f646aef1fc921478bce1f35e9071bf7b","throwable":""}
today at 16:14 {"timestamp":"2021-11-19T08:14:30,473","container":"15590c1d9d97","level":"INFO","thread":"main","class":"DefaultSynchronizer","message":"Starting synchronizer.","throwable":""}
today at 16:14 {"timestamp":"2021-11-19T08:14:30,475","container":"15590c1d9d97","level":"INFO","thread":"main","class":"FullSyncDownloader","message":"Starting full sync.","throwable":""}
today at 16:14 {"timestamp":"2021-11-19T08:14:30,475","container":"15590c1d9d97","level":"INFO","thread":"main","class":"FullSyncTargetManager","message":"No sync target, waiting for peers: 0","throwable":""}
today at 16:14 {"timestamp":"2021-11-19T08:14:30,791","container":"15590c1d9d97","level":"INFO","thread":"nioEventLoopGroup-3-9","class":"FullSyncTargetManager","message":"No sync target, waiting for peers: 9","throwable":""}
today at 16:14 {"timestamp":"2021-11-19T08:14:59,846","container":"15590c1d9d97","level":"INFO","thread":"main","class":"JsonRpcHttpService","message":"Starting JSON-RPC service on 0.0.0.0:8545","throwable":""}
today at 16:14 {"timestamp":"2021-11-19T08:14:59,877","container":"15590c1d9d97","level":"INFO","thread":"main","class":"GraphQLHttpService","message":"Starting GraphQL HTTP service on 0.0.0.0:8547","throwable":""}
today at 16:14 {"timestamp":"2021-11-19T08:14:59,876","container":"15590c1d9d97","level":"INFO","thread":"vert.x-eventloop-thread-8","class":"JsonRpcHttpService","message":"JSON-RPC service started and listening on 0.0.0.0:8545","throwable":""}
today at 16:14 {"timestamp":"2021-11-19T08:14:59,881","container":"15590c1d9d97","level":"INFO","thread":"main","class":"WebSocketService","message":"Starting Websocket service on 0.0.0.0:8546","throwable":""}
today at 16:14 {"timestamp":"2021-11-19T08:14:59,881","container":"15590c1d9d97","level":"INFO","thread":"vert.x-eventloop-thread-10","class":"GraphQLHttpService","message":"GraphQL HTTP service started and listening on 0.0.0.0:8547","throwable":""}
today at 16:14 {"timestamp":"2021-11-19T08:14:59,893","container":"15590c1d9d97","level":"INFO","thread":"vert.x-eventloop-thread-12","class":"WebSocketService","message":"Websocket service started and listening on 0.0.0.0:8546","throwable":""}
today at 16:14 {"timestamp":"2021-11-19T08:14:59,895","container":"15590c1d9d97","level":"INFO","thread":"main","class":"Runner","message":"Ethereum main loop is up.","throwable":""}
today at 16:14 {"timestamp":"2021-11-19T08:14:59,909","container":"15590c1d9d97","level":"INFO","thread":"main","class":"AutoTransactionLogBloomCachingService","message":"Starting auto transaction log bloom caching service.","throwable":""}
today at 16:14 {"timestamp":"2021-11-19T08:14:59,911","container":"15590c1d9d97","level":"INFO","thread":"main","class":"LogBloomCacheMetadata","message":"Lookup cache metadata file in data directory: /opt/besu/data/caches","throwable":""}
today at 16:17 {"timestamp":"2021-11-19T08:17:46,656","container":"15590c1d9d97","level":"INFO","thread":"pool-9-thread-1","class":"IbftRound","message":"Importing block to chain. round=ConsensusRoundIdentifier{Sequence=9702015, Round=4}, hash=0xa91b22545f94a67c23d7c1d6a3353584b4129a58453fe53360909dc246f40403","throwable":""}
today at 16:18 {"timestamp":"2021-11-19T08:18:16,237","container":"15590c1d9d97","level":"WARN","thread":"vertx-blocked-thread-checker","class":"BlockedThreadChecker","message":"Thread Thread[vert.x-eventloop-thread-4,5,main]=Thread[vert.x-eventloop-thread-4,5,main] has been blocked for 2485 ms, time limit is 2000 ms","throwable":""}
today at 16:18 {"timestamp":"2021-11-19T08:18:16,263","container":"15590c1d9d97","level":"WARN","thread":"vertx-blocked-thread-checker","class":"BlockedThreadChecker","message":"Thread Thread[vert.x-eventloop-thread-4,5,main]=Thread[vert.x-eventloop-thread-4,5,main] has been blocked for 7515 ms, time limit is 2000 ms","throwable":" io.vertx.core.VertxException: Thread blocked\n\tat [email protected]/jdk.internal.misc.VM.getNanoTimeAdjustment(Native Method)\n\tat [email protected]/java.time.Clock$SystemClock.instant(Unknown Source)\n\tat [email protected]/java.time.Instant.now(Unknown Source)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.PacketData.defaultExpiration(PacketData.java:37)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.FindNeighborsPacketData.create(FindNeighborsPacketData.java:42)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.PeerDiscoveryController.lambda$findNodes$14(PeerDiscoveryController.java:536)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.PeerDiscoveryController$$Lambda$1226/0x000000084066d440.accept(Unknown Source)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.PeerDiscoveryController$PeerInteractionState.execute(PeerDiscoveryController.java:702)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.PeerDiscoveryController.dispatchInteraction(PeerDiscoveryController.java:558)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.PeerDiscoveryController.findNodes(PeerDiscoveryController.java:541)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.PeerDiscoveryController$$Lambda$1130/0x0000000840637c40.findNeighbours(Unknown Source)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.RecursivePeerRefreshState.neighboursInitiateRound(RecursivePeerRefreshState.java:165)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.RecursivePeerRefreshState.bondingInitiateRound(RecursivePeerRefreshState.java:110)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.RecursivePeerRefreshState.neighboursCancelOutstandingRequests(RecursivePeerRefreshState.java:179)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.RecursivePeerRefreshState$$Lambda$1229/0x000000084066c040.run(Unknown Source)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.RecursivePeerRefreshState.performIfNotCancelled(RecursivePeerRefreshState.java:132)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.RecursivePeerRefreshState.lambda$scheduleTimeout$0(RecursivePeerRefreshState.java:126)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.RecursivePeerRefreshState$$Lambda$1159/0x0000000840642c40.handle(Unknown Source)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.VertxTimerUtil.lambda$setTimer$1(VertxTimerUtil.java:34)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.VertxTimerUtil$$Lambda$1156/0x0000000840642040.handle(Unknown Source)\n\tat app//io.vertx.core.impl.VertxImpl$InternalTimerHandler.handle(VertxImpl.java:942)\n\tat app//io.vertx.core.impl.VertxImpl$InternalTimerHandler.handle(VertxImpl.java:906)\n\tat app//io.vertx.core.impl.ContextImpl.executeTask(ContextImpl.java:366)\n\tat app//io.vertx.core.impl.EventLoopContext.execute(EventLoopContext.java:43)\n\tat app//io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:229)\n\tat app//io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:221)\n\tat app//io.vertx.core.impl.VertxImpl$InternalTimerHandler.run(VertxImpl.java:932)\n\tat app//io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)\n\tat app//io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170)\n\tat app//io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)\n\tat app//io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469)\n\tat app//io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:497)\n\tat app//io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)\n\tat app//io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)\n\tat app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\tat [email protected]/java.lang.Thread.run(Unknown Source)\n"}
today at 16:18 {"timestamp":"2021-11-19T08:18:22,869","container":"15590c1d9d97","level":"INFO","thread":"pool-9-thread-1","class":"IbftBesuControllerBuilder","message":"Imported #9,702,015 / 2 tx / 0 pending / 9,875,025 (0.0%) gas / (0xa91b22545f94a67c23d7c1d6a3353584b4129a58453fe53360909dc246f40403)","throwable":""}
today at 16:18 {"timestamp":"2021-11-19T08:18:22,869","container":"15590c1d9d97","level":"INFO","thread":"EthScheduler-Workers-0","class":"PersistBlockTask","message":"Imported #9,702,015 / 2 tx / 0 om / 9,875,025 (0.0%) gas / (0xa91b22545f94a67c23d7c1d6a3353584b4129a58453fe53360909dc246f40403) in 0.661s. Peers: 5","throwable":""}
today at 16:19 {"timestamp":"2021-11-19T08:18:57,578","container":"15590c1d9d97","level":"WARN","thread":"vertx-blocked-thread-checker","class":"BlockedThreadChecker","message":"Thread Thread[vert.x-eventloop-thread-4,5,main]=Thread[vert.x-eventloop-thread-4,5,main] has been blocked for 2249 ms, time limit is 2000 ms","throwable":""}
today at 16:21 {"timestamp":"2021-11-19T08:21:22,802","container":"15590c1d9d97","level":"WARN","thread":"vertx-blocked-thread-checker","class":"BlockedThreadChecker","message":"Thread Thread[vert.x-eventloop-thread-4,5,main]=Thread[vert.x-eventloop-thread-4,5,main] has been blocked for 5416 ms, time limit is 2000 ms","throwable":" io.vertx.core.VertxException: Thread blocked\n\tat [email protected]/java.util.stream.ReferencePipeline.limit(Unknown Source)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.RecursivePeerRefreshState.neighboursRoundCandidates(RecursivePeerRefreshState.java:258)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.RecursivePeerRefreshState.neighboursInitiateRound(RecursivePeerRefreshState.java:150)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.RecursivePeerRefreshState.bondingInitiateRound(RecursivePeerRefreshState.java:110)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.RecursivePeerRefreshState.neighboursCancelOutstandingRequests(RecursivePeerRefreshState.java:179)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.RecursivePeerRefreshState$$Lambda$1229/0x000000084066c040.run(Unknown Source)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.RecursivePeerRefreshState.performIfNotCancelled(RecursivePeerRefreshState.java:132)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.RecursivePeerRefreshState.lambda$scheduleTimeout$0(RecursivePeerRefreshState.java:126)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.RecursivePeerRefreshState$$Lambda$1159/0x0000000840642c40.handle(Unknown Source)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.VertxTimerUtil.lambda$setTimer$1(VertxTimerUtil.java:34)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.VertxTimerUtil$$Lambda$1156/0x0000000840642040.handle(Unknown Source)\n\tat app//io.vertx.core.impl.VertxImpl$InternalTimerHandler.handle(VertxImpl.java:942)\n\tat app//io.vertx.core.impl.VertxImpl$InternalTimerHandler.handle(VertxImpl.java:906)\n\tat app//io.vertx.core.impl.ContextImpl.executeTask(ContextImpl.java:366)\n\tat app//io.vertx.core.impl.EventLoopContext.execute(EventLoopContext.java:43)\n\tat app//io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:229)\n\tat app//io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:221)\n\tat app//io.vertx.core.impl.VertxImpl$InternalTimerHandler.run(VertxImpl.java:932)\n\tat app//io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)\n\tat app//io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170)\n\tat app//io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)\n\tat app//io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469)\n\tat app//io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:500)\n\tat app//io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)\n\tat app//io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)\n\tat app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\tat [email protected]/java.lang.Thread.run(Unknown Source)\n"}
today at 16:21 {"timestamp":"2021-11-19T08:21:22,873","container":"15590c1d9d97","level":"WARN","thread":"vertx-blocked-thread-checker","class":"BlockedThreadChecker","message":"Thread Thread[vert.x-worker-thread-16,5,main]=Thread[vert.x-worker-thread-16,5,main] has been blocked for 126543 ms, time limit is 60000 ms","throwable":" io.vertx.core.VertxException: Thread blocked\n\tat app//org.hyperledger.besu.nativelib.secp256k1.LibSecp256k1.secp256k1_ecdsa_recover(Native Method)\n\tat app//org.hyperledger.besu.crypto.SECP256K1.recoverFromSignatureNative(SECP256K1.java:223)\n\tat app//org.hyperledger.besu.crypto.SECP256K1.recoverFromSignature(SECP256K1.java:197)\n\tat app//org.hyperledger.besu.crypto.AbstractSECP256.normaliseSignature(AbstractSECP256.java:109)\n\tat app//org.hyperledger.besu.crypto.NodeKey.sign(NodeKey.java:34)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.Packet.(Packet.java:64)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.Packet.create(Packet.java:99)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.PeerDiscoveryController.lambda$createPacket$12(PeerDiscoveryController.java:518)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.PeerDiscoveryController$$Lambda$1147/0x0000000840633440.get(Unknown Source)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.VertxPeerDiscoveryAgent$VertxAsyncExecutor.lambda$execute$0(VertxPeerDiscoveryAgent.java:254)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.VertxPeerDiscoveryAgent$VertxAsyncExecutor$$Lambda$1148/0x0000000840632840.handle(Unknown Source)\n\tat app//io.vertx.core.impl.ContextImpl.lambda$executeBlocking$2(ContextImpl.java:313)\n\tat app//io.vertx.core.impl.ContextImpl$$Lambda$1150/0x0000000840632040.run(Unknown Source)\n\tat [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)\n\tat [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)\n\tat app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\tat [email protected]/java.lang.Thread.run(Unknown Source)\n"}
today at 16:21 {"timestamp":"2021-11-19T08:21:22,880","container":"15590c1d9d97","level":"WARN","thread":"vertx-blocked-thread-checker","class":"BlockedThreadChecker","message":"Thread Thread[vert.x-worker-thread-9,5,main]=Thread[vert.x-worker-thread-9,5,main] has been blocked for 120552 ms, time limit is 60000 ms","throwable":" io.vertx.core.VertxException: Thread blocked\n\tat app//org.hyperledger.besu.nativelib.secp256k1.LibSecp256k1.secp256k1_ecdsa_sign_recoverable(Native Method)\n\tat app//org.hyperledger.besu.crypto.SECP256K1.signNative(SECP256K1.java:141)\n\tat app//org.hyperledger.besu.crypto.SECP256K1.sign(SECP256K1.java:91)\n\tat app//org.hyperledger.besu.crypto.KeyPairSecurityModule.sign(KeyPairSecurityModule.java:57)\n\tat app//org.hyperledger.besu.crypto.NodeKey.sign(NodeKey.java:32)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.Packet.(Packet.java:64)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.Packet.create(Packet.java:99)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.PeerDiscoveryController.lambda$createPacket$12(PeerDiscoveryController.java:518)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.internal.PeerDiscoveryController$$Lambda$1147/0x0000000840633440.get(Unknown Source)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.VertxPeerDiscoveryAgent$VertxAsyncExecutor.lambda$execute$0(VertxPeerDiscoveryAgent.java:254)\n\tat app//org.hyperledger.besu.ethereum.p2p.discovery.VertxPeerDiscoveryAgent$VertxAsyncExecutor$$Lambda$1148/0x0000000840632840.handle(Unknown Source)\n\tat app//io.vertx.core.impl.ContextImpl.lambda$executeBlocking$2(ContextImpl.java:313)\n\tat app//io.vertx.core.impl.ContextImpl$$Lambda$1150/0x0000000840632040.run(Unknown Source)\n\tat [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)\n\tat [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)\n\tat app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\tat [email protected]/java.lang.Thread.run(Unknown Source)\n"}

@MadelineMurray

@macfarla macfarla self-assigned this Nov 30, 2021
@macfarla
Copy link
Contributor

Hi @eu09 I am working on reproducing this. So far I can't reproduce it locally (the call gets status 0x0 but I don't see the CPU/memory problems you describe) locally (ethash network, running on my local machine, and I've tried latest main branch and 21.10.2). I've only tried as a public contract - confirming you are not deploying this as a private contract? I haven't had too much to do with solidity assembly so may need to do some more research into that.

@macfarla
Copy link
Contributor

macfarla commented Dec 1, 2021

I have also tried with the quickstart using besu version (21.7.4 and) 21.10.2 using QBFT/IBFT2 and I don't see any issues with memory/CPU when I deploy or call these contracts.

Can you describe how you are deploying the contracts and sending the transactions? Wondering if there is something different about the way the transactions are being constructed. (eg calldatasize may be large)

Also what version of solidity compiler are you using? Actually it might help if you send the contract binary code, so we can see if they are different?

@macfarla macfarla added the P3 Medium (ex: JSON-RPC request not working with a specific client library due to loose spec assumtion) label Dec 1, 2021
@eu09
Copy link
Author

eu09 commented Dec 1, 2021

We use truffle to compile and deploy the contracts, then just simply send the transaction by web3.js . oomContract.methods.callMe("0x...").send(...)
Our normal development also uses the same settings and works fine so far, so it should have little relation to the issue.

Tools version:
Truffle v5.4.16 (core: 5.4.16)
Solidity - 0.6.6 (solc-js)
Node v14.17.2
Web3.js v1.5.3

The Besu Service located in Docker Container. Each Service is limited in Min 2GB Max 4GB on JVM options
Here below is config of the docker-composer
x-besu-bootnode-def:
&besu-bootnode-def
restart: "on-failure"
image: hyperledger/besu:21.10.2
environment:
- BESU_OPTS=-Xms4g -Xmx8g
- LOG4J_CONFIGURATION_FILE=/config/log-config.xml

x-besu-def:
&besu-def
restart: "on-failure"
image: hyperledger/besu:21.10.2
environment:
- LOG4J_CONFIGURATION_FILE=/config/log-config.xml
- BESU_OPTS=-Xms4g -Xmx8g

@macfarla
Copy link
Contributor

macfarla commented Dec 2, 2021

@eu09 this is what I get for the binaries of those contracts - are yours different?
cat Contract.bin
608060405234801561001057600080fd5b506101ca806100206000396000f3fe608060405234801561001057600080fd5b506004361061002b5760003560e01c8063b27b880414610030575b600080fd5b61004a6004803603810190610045919061009c565b61004c565b005b6040517f08c379a000000000000000000000000000000000000000000000000000000000815260040161007e906100ec565b60405180910390fd5b6000813590506100968161017d565b92915050565b6000602082840312156100b2576100b161014f565b5b60006100c084828501610087565b91505092915050565b60006100d6600d8361010c565b91506100e182610154565b602082019050919050565b60006020820190508181036000830152610105816100c9565b9050919050565b600082825260208201905092915050565b60006101288261012f565b9050919050565b600073ffffffffffffffffffffffffffffffffffffffff82169050919050565b600080fd5b7f52657665727420616e7977617900000000000000000000000000000000000000600082015250565b6101868161011d565b811461019157600080fd5b5056fea2646970667358221220f98aead7839d4b5cb2fa52561c9b1720603885870f500dc934de148dcdea6e8164736f6c63430008060033
cat OOM.bin
608060405234801561001057600080fd5b50610274806100206000396000f3fe608060405234801561001057600080fd5b506004361061002b5760003560e01c8063b27b880414610030575b600080fd5b61004a60048036038101906100459190610108565b61004c565b005b60606000806000604051935036600085376000803686885af490503d9150816000853e806000811461007d57610093565b60008311156100925761012085019350836040525b5b5060008114156100ec578473ffffffffffffffffffffffffffffffffffffffff167f410d96db3f80b0f89b36888c4d8a94004268f8d42309ac39b7bcba706293e099856040516100e3919061016e565b60405180910390a25b5050505050565b60008135905061010281610227565b92915050565b60006020828403121561011e5761011d610211565b5b600061012c848285016100f3565b91505092915050565b600061014082610190565b61014a818561019b565b935061015a8185602086016101de565b61016381610216565b840191505092915050565b600060208201905081810360008301526101888184610135565b905092915050565b600081519050919050565b600082825260208201905092915050565b60006101b7826101be565b9050919050565b600073ffffffffffffffffffffffffffffffffffffffff82169050919050565b60005b838110156101fc5780820151818401526020810190506101e1565b8381111561020b576000848401525b50505050565b600080fd5b6000601f19601f8301169050919050565b610230816101ac565b811461023b57600080fd5b5056fea2646970667358221220fdfb5c371055342507b8fb9ca7b0c234f79819bd5cb05c0d467fb605de979eb564736f6c63430008060033

@elohffa
Copy link

elohffa commented Dec 3, 2021

We have custom solc settings in truffle-config.js, so the compiled bytecode are different.
{
optimizer: {
enabled: true,
runs: 200
},
evmVersion: "istanbul"
}

Contract
6080604052348015600f57600080fd5b5060c58061001e6000396000f3fe6080604052348015600f57600080fd5b506004361060285760003560e01c8063b27b880414602d575b600080fd5b605060048036036020811015604157600080fd5b50356001600160a01b03166052565b005b6040805162461bcd60e51b815260206004820152600d60248201526c52657665727420616e7977617960981b604482015290519081900360640190fdfea2646970667358221220ab0ae18364d8bc77816c4403af0321b94d8c64bfcf78de34c1ac975a38df507a64736f6c63430006060033

OOM
608060405234801561001057600080fd5b5061017a806100206000396000f3fe608060405234801561001057600080fd5b506004361061002b5760003560e01c8063b27b880414610030575b600080fd5b6100566004803603602081101561004657600080fd5b50356001600160a01b0316610058565b005b60405160008080368185376000803686885af490503d9150816000853e80801561008157610093565b82156100935761012085019350836040525b508061013d57846001600160a01b03167f410d96db3f80b0f89b36888c4d8a94004268f8d42309ac39b7bcba706293e099856040518080602001828103825283818151815260200191508051906020019080838360005b838110156101025781810151838201526020016100ea565b50505050905090810190601f16801561012f5780820380516001836020036101000a031916815260200191505b509250505060405180910390a25b505050505056fea2646970667358221220e205eab0fed611629d6d7c1c6b0f1236988e82ccf408bd002b46112baf2990b764736f6c63430006060033

@elohffa
Copy link

elohffa commented Dec 3, 2021

Using this version of solc: 0.6.6+commit.6c089d02.Emscripten.clang

@pinges pinges assigned RP27 and unassigned macfarla Dec 8, 2021
@RP27
Copy link
Contributor

RP27 commented Dec 10, 2021

We weren't able to reproduce this issue after deploying the contract with the binary values we got locally from our machines, nor the binary values you have provided.

Can you confirm the memory allocation for the Docker container? Is it min 2, max 4 or min 4, max 8?

@rinor
Copy link

rinor commented Dec 10, 2021

@RP27
Let me provide some more info and context in the hope it can help. We did some internal tests and observed as follows.

The main concern here is the high resource usage when executing that call.

The node can hang/crash or not depends on the hardware (vm/container) type/resources and also on the block size (gas limit).
For instance testing in one small instance (local machine) we observed the following cpu/mem bumps while executing the call to rpcnode:

                   CPU %     MEM USAGE
validator1_1       6.40%     679.5MiB
validator2_1       2.76%     471.4MiB
validator3_1       5.89%     488.2MiB
validator4_1       6.35%     472.1MiB
rpcnode          207.70%      1.51GiB

during that high usage the logs report several times (log cleaned)

{
  "timestamp": "2021-12-02T19:47:45,365",
  "container": "70a0f942ae46",
  "level": "WARN",
  "thread": "vertx-blocked-thread-checker",
  "class": "BlockedThreadChecker",
  "message": "Thread Thread[vert.x-worker-thread-0,5,main]=Thread[vert.x-worker-thread-0,5,main] has been blocked for 124379 ms, time limit is 60000 ms",
  "throwable": " io.vertx.core.VertxException: Thread blocked "
               " at app//org.hyperledger.besu.evm.frame.MessageFrame.writeMemoryRightAligned(MessageFrame.java:648) "
               " at app//org.hyperledger.besu.evm.operation.MStoreOperation.execute(MStoreOperation.java:46) "
               " at app//org.hyperledger.besu.evm.EVM.lambda$executeNextOperation$0(EVM.java:86) "
               " at app//org.hyperledger.besu.evm.EVM$$Lambda$1530/0x0000000840746440.execute(Unknown Source) "
               " at app//org.hyperledger.besu.evm.tracing.EstimateGasOperationTracer.traceExecution(EstimateGasOperationTracer.java:31) "
               " at app//org.hyperledger.besu.evm.EVM.executeNextOperation(EVM.java:80) "
               " at app//org.hyperledger.besu.evm.EVM.runToHalt(EVM.java:73) "
               " at app//org.hyperledger.besu.evm.processor.AbstractMessageProcessor.codeExecute(AbstractMessageProcessor.java:157) "
               " at app//org.hyperledger.besu.evm.processor.AbstractMessageProcessor.process(AbstractMessageProcessor.java:169) "
               " at app//org.hyperledger.besu.ethereum.mainnet.MainnetTransactionProcessor.process(MainnetTransactionProcessor.java:489) "
               " at app//org.hyperledger.besu.ethereum.mainnet.MainnetTransactionProcessor.processTransaction(MainnetTransactionProcessor.java:397) "
               " at app//org.hyperledger.besu.ethereum.mainnet.MainnetTransactionProcessor.processTransaction(MainnetTransactionProcessor.java:148) "
               " at app//org.hyperledger.besu.ethereum.transaction.TransactionSimulator.process(TransactionSimulator.java:222) "
               " at app//org.hyperledger.besu.ethereum.transaction.TransactionSimulator.process(TransactionSimulator.java:107) "
               " at app//org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.EthEstimateGas.response(EthEstimateGas.java:81) "
               " at app//org.hyperledger.besu.ethereum.api.jsonrpc.JsonRpcHttpService.process(JsonRpcHttpService.java:725) "
               " at app//org.hyperledger.besu.ethereum.api.jsonrpc.JsonRpcHttpService.lambda$handleJsonSingleRequest$13(JsonRpcHttpService.java:579) "
               " at app//org.hyperledger.besu.ethereum.api.jsonrpc.JsonRpcHttpService$$Lambda$1494/0x0000000840726040.handle(Unknown Source) "
               " at app//io.vertx.core.impl.ContextImpl.lambda$executeBlocking$2(ContextImpl.java:313) "
               " at app//io.vertx.core.impl.ContextImpl$$Lambda$1006/0x0000000840580c40.run(Unknown Source) "
               " at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) "
               " at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) "
               " at app//io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) "
               " at [email protected]/java.lang.Thread.run(Unknown Source)"
}

this shows 3 calls "high" cpu usage duration example:
gasLimit -> 60_000_000
besu_oom_kill

After a wile (in the example ~2 minutes) the node recovers and back to normal.
Doing the same in the same setup but just lowering the block size (gas limits) results in much lower "high" resources usage duration and faster recovery times as shown:
gasLimit -> 16_000_000
besu_oom_kill_smaller_block


Now doing the same tests on more powerful machines the high usage (due to available resources the cpu usage was about 400%) is about 3-5 seconds (instead of ~2 minutes) and no warning logs reported (since the thread lock time < time limit ).

We didn't test with the highest gasLimit value (as the op reports) since that's not an option for us and the spike was worrying enough for us to investigate further.

@RP27
Copy link
Contributor

RP27 commented Dec 21, 2021

We have made attempts to reproduce the high CPU usage issue when making that call, but we have been unsuccessful so far in doing so. We have tried with a Besu node running in a docker container with min 1/max 2, min 2/max 4 and min 4/max 8gb of memory. We have also attempted to run the container with just 1 CPU core.

Are you able to provide the web3js code you are using to construct the calls to the contracts?

Also might be useful if you can provide a mini standalone repository that produces the issue, which we can checkout and work with.

@RP27
Copy link
Contributor

RP27 commented Jan 5, 2022

@rinor
In conducting further tests, there appears to be an issue, similar to the one reported, with a spike in the CPU usage occurring when calling the callMe function in OOM via truffle migrate. Though, this is slightly different in the sense that it will not return to regular CPU usage after a few minutes, and it will effectively kill Besu. There also appears to be a large spike in the GC time and memory usage until Besu is killed. This test was conducted with Besu running in a docker container with limited resources.

As mentioned in my previous reply, it would be very useful for us if you could provide a repository that can reproduce this issue, along with your web3js code.

@macfarla macfarla added the TeamRevenant GH issues worked on by Revenant Team label Jan 6, 2022
@frankisawesome
Copy link
Contributor

I was able to help @RP27 replicate this (deploying the contracts twice and Besu starts creating threads until it reaches the limit and start throwing exceptions)

@drinkcoffee
Copy link
Contributor

drinkcoffee commented Feb 2, 2022

Looking at the code:
function callMe(address addr) external {
bytes memory ptr;
uint256 offset;
uint256 size;
uint256 result;

    assembly {
        ptr := mload(0x40)
        calldatacopy(ptr, 0, calldatasize())
        result := delegatecall(gas(), addr, ptr, calldatasize(), 0, 0)
        size := returndatasize()
        returndatacopy(ptr, 0, size)

The call data is copies from this entry point contract to call to the contract being delegated to.
If by mistake, addr was the address of contract OOM rather than contract Contract, then you would expect to see an infinite loop.

Maybe confirm that accidentally, the address being passed into callMe isn't the address of the contract OOM.

@macfarla macfarla assigned pinges and unassigned RP27 Feb 4, 2022
@frankisawesome
Copy link
Contributor

Apologies for the delay.

We've done some more testing, and it seems like Besu's behaviour handling the contract call is inline with other clients we've tested, in a 0 gas environment there's an issue with the contract that freaks the EVM out.

What's the use case for manually assigning an offset with add(ptr, 0x120) and storing it at 0x40? This is probably not done correctly.

contract OOM {
    event Reverted(address indexed addr, bytes ptr);

    function callMe(address addr) external {
        bytes memory ptr;
        // uint256 offset;
        uint256 size;
        uint256 result;

        assembly {
            ptr := mload(0x40)
            calldatacopy(ptr, 0, calldatasize())
            result := delegatecall(gas(), addr, ptr, calldatasize(), 0, 0)
            size := returndatasize()
            returndatacopy(ptr, 0, size)

            // switch result
            // case 0 {
            //     if gt(size, 0) {
            //         let newPtr := mload(0x40)
            //         mstore(0x40, add(newPtr, and(add(add(size, 0x20), 0x1f), not(0x1f))))
            //     }
            // }
            switch result
            case 0 { revert(ptr, size) }
            default { return(ptr, size) }
        }
        // if (result == 0) {
        //     emit Reverted(addr, ptr);
        // }
    }
}

Something like this works quite well (ignore the comments)

cc @elohffa @eu09

@drinkcoffee
Copy link
Contributor

the contract that freaks the EVM out

See the code in question below. Is the issue that the following code causes ptr to not point to a valid bytes object. When the emit is called, the bytes that ptr points to is copied for the purposes of emitting an event.

My guess is that the location ptr points to is interpreted as the bytes object having a very large length (think 2**256). Because the length field of ptr is very large, the EVM spends a lot of time copying bytes (it could keep trying to copy until the computer runs out of memory). In a configuration where gas wasn't zero, the transaction would run out of gas quickly and stop.

offset := add(ptr, 0x120)
mstore(0x40, offset)
emit Reverted(addr, ptr);

@MadelineMurray
Copy link
Contributor

hi @eu09 - we've reproduced the memory spike on other clients so are closing this one. Please reopen if you have any further questions.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working P3 Medium (ex: JSON-RPC request not working with a specific client library due to loose spec assumtion) TeamRevenant GH issues worked on by Revenant Team
Projects
None yet
Development

No branches or pull requests

9 participants