One sendMessage generates a lot of send_message calls

[grishasobol]

Problem

For long running smart contracts one sendMessage call generates big (can be infinity) number of send_message calls: pallet_gear::pallet::Pallet::send_message. This cause that some smart contracts can be executed many times (sometimes will be executed endlessly).

Steps

1. cd /path/to/gear
2. git checkout send-msg-bug
3. cargo build -p gear-node --features debug-mode
4. make examples yamls=./examples/inf_loop/inf_loop.yaml
5. ./target/debug/gear-node purge-chain --dev
6. RUST_LOG=debug ./target/debug/gear-node --dev --ws-max-out-buffer-capacity 500 --rpc-max-payload 500 -l 4 >out 2>&1

Go to other terminal/console tab, in order to call rpc-tests

6. cd /path/to/gear
7. cd rpc-tests && npm i && npm run build && cd -
8. node rpc-tests/dist/index.js examples/inf_loop/inf_loop.yaml

After you see something like that:

Total fixtures: 1
5GrwvaEF5zXb26Fz9rcQpDWS57CtERHpNehXCPcNoHGKutQY
{ method: 'DebugMode', data: true }
Test: inf loop

You can drop index.js execution using Ctrl + c

9. Because we redirect all gear-node output to out file in gear dir, we can check how many times send_message has been called already:

$ cat out | grep "KEK: send message" | wc -l
9

9 is number of send_message calls in my case and it will increase may be forever. You can check that while gear-node is running new and new messages with same id will appear in message queue. This will cause new and new execution of our smart contract: demo-inf-loop .

You can also investigate the same behaviour using polkadot.js.org/apps , so it's not the problem of rpc-tests.

Possible Solution

I suppose that problem may be in gear node-js api , because send_message is called from that api.

[gshep]

Investigated a bit and the reason is that process_queue (and on_idle callback correspondingly) exceeds block Weight limit.

The following output is produced on release gear-node running on AMD Ryzen 7 3700X/32GiB RAM/SSD:

2022-01-17 12:28:31 ✨ Imported #43 (0x7fe0…8962)    
2022-01-17 12:28:32 🙌 Starting consensus session on top of parent 0x7fe0d49ee1c56345d0b2fe643eb9714a7eca1fb58498faf47901120374928962    
2022-01-17 12:28:32 ⌛️ Discarding proposal for slot 1642408112; block production took too long    
2022-01-17 12:28:33 🙌 Starting consensus session on top of parent 0x7fe0d49ee1c56345d0b2fe643eb9714a7eca1fb58498faf47901120374928962    
2022-01-17 12:28:33 💤 Idle (0 peers), best: #43 (0x7fe0…8962), finalized #41 (0x3912…46be), ⬇ 0 ⬆ 0    
2022-01-17 12:28:34 ⌛️ Discarding proposal for slot 1642408113; block production took too long    
2022-01-17 12:28:34 🙌 Starting consensus session on top of parent 0x7fe0d49ee1c56345d0b2fe643eb9714a7eca1fb58498faf47901120374928962    
2022-01-17 12:28:36 ⌛️ Discarding proposal for slot 1642408114; block production took too long    
2022-01-17 12:28:36 🙌 Starting consensus session on top of parent 0x7fe0d49ee1c56345d0b2fe643eb9714a7eca1fb58498faf47901120374928962    
2022-01-17 12:28:38 💤 Idle (0 peers), best: #43 (0x7fe0…8962), finalized #41 (0x3912…46be), ⬇ 0 ⬆ 0    
2022-01-17 12:28:39 ⌛️ Discarding proposal for slot 1642408116; block production took too long    
2022-01-17 12:28:39 🙌 Starting consensus session on top of parent 0x7fe0d49ee1c56345d0b2fe643eb9714a7eca1fb58498faf47901120374928962    
2022-01-17 12:28:43 charge_gas: 1000, gas_counter = GasCounter { left: 0, burned: 100000000000 }    
2022-01-17 12:28:43 🎁 Prepared block for proposing at 44 [hash: 0x3664d2d53f9d447d8fc8c27ff7fc4406e4705f00787473606d4ee34ff68cbf87; parent_hash: 0x7fe0…8962; extrinsics (2): [0x88be…bfe8, 0x8a4a…35b4]]    
2022-01-17 12:28:43 💤 Idle (0 peers), best: #43 (0x7fe0…8962), finalized #41 (0x3912…46be), ⬇ 0 ⬆ 0    
2022-01-17 12:28:44 charge_gas: 1000, gas_counter = GasCounter { left: 0, burned: 100000000000 }    
2022-01-17 12:28:44 🎁 Prepared block for proposing at 44 [hash: 0x8409ed34eff8e8d118fc79f5fe6135bebc44c691af6a81ce44886b574fc7d930; parent_hash: 0x7fe0…8962; extrinsics (2): [0x67c2…faf5, 0x8a4a…35b4]]    
2022-01-17 12:28:45 ⌛️ Discarding proposal for slot 1642408119; block production took too long    
2022-01-17 12:28:45 🙌 Starting consensus session on top of parent 0x7fe0d49ee1c56345d0b2fe643eb9714a7eca1fb58498faf47901120374928962    
2022-01-17 12:28:45 charge_gas: 1000, gas_counter = GasCounter { left: 0, burned: 100000000000 }    
2022-01-17 12:28:45 🎁 Prepared block for proposing at 44 [hash: 0x233cfeb87cded208edae13a727586ab20645c7db87435b0da33e6caaac87e3d9; parent_hash: 0x7fe0…8962; extrinsics (2): [0x21ec…4784, 0x8a4a…35b4]]    
2022-01-17 12:28:47 charge_gas: 1000, gas_counter = GasCounter { left: 0, burned: 100000000000 }    
2022-01-17 12:28:47 🎁 Prepared block for proposing at 44 [hash: 0xc57833240d357ed0b20929e2c3c46acb400f0900e79e646edbe0d6817f851192; parent_hash: 0x7fe0…8962; extrinsics (2): [0xb480…42a9, 0x8a4a…35b4]]    
2022-01-17 12:28:48 💤 Idle (0 peers), best: #43 (0x7fe0…8962), finalized #41 (0x3912…46be), ⬇ 0 ⬆ 0    
2022-01-17 12:28:50 charge_gas: 1000, gas_counter = GasCounter { left: 0, burned: 100000000000 }    
2022-01-17 12:28:50 🎁 Prepared block for proposing at 44 [hash: 0x116743356d78580ad1633c73a7e7bcfa4304a2e4f6d2f4f4574ba957214cd722; parent_hash: 0x7fe0…8962; extrinsics (2): [0x8135…e9e9, 0x8a4a…35b4]]    
2022-01-17 12:28:53 💤 Idle (0 peers), best: #43 (0x7fe0…8962), finalized #41 (0x3912…46be), ⬇ 0 ⬆ 0    
2022-01-17 12:28:56 charge_gas: 1000, gas_counter = GasCounter { left: 0, burned: 100000000000 }    
2022-01-17 12:28:56 🎁 Prepared block for proposing at 44 [hash: 0xd2295fc09a106d4c75e6aed0690ae5d0effb46244456572879fad2fa77ea2336; parent_hash: 0x7fe0…8962; extrinsics (2): [0xf7ae…b2a1, 0x8a4a…35b4]]    
2022-01-17 12:28:56 🔖 Pre-sealed block for proposal at 44. Hash now 0xd7fcc299831a9c6af5b8a4f8db890c5c68d4f71088168f23275dc51e9d540794, previously 0xd2295fc09a106d4c75e6aed0690ae5d0effb46244456572879fad2fa77ea2336.    
2022-01-17 12:28:56 ✨ Imported #44 (0xd7fc…0794)    

There is a related task - #528 . The intention was to more accurately calculate time spent in process_queue though the suggested function may be used to constraint programs' execution time.

Another solution is to change gas amount charging for instructions.

[grishasobol]

Currently problem for inf_loop is solved. But we also have to make test which will check the case.