order leakage

[cipig]

MM2 from dev branch (which seems to fix the deadlock reported in #1172) leaks orders. Their number (as seen from seednodes) increase all the time till it reaches a point where seed nodes disconnect you. This happens on all my nodes, does not matter how many orders they initially had.

This is the real number of orders from all my nodes (when running from mm2.1 branch, so without the leak):

02dbd8c73e2e80e4f3cf88d2f04a9d2d0df4269496608b14a3e17556fdcb01e0c1 #### orders_uuids=1332
031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8 #### orders_uuids=2634
0315d9c51c657ab1be4ae9d3ab6e76a619d3bccfe830d5363fa168424c0d044732 #### orders_uuids=1423
03de96cb66dcfaceaa8b3d4993ce8914cd5fe84e3fd53cefdae45add8032792a12 #### orders_uuids=1096

When running from dev branch, the number of orders increases slowly but steadily over time. This is from the node that actually has orders_uuids=2634 after running for couple hours:

· 2021-12-20 09:06:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=5223 orders_uuids=2735
· 2021-12-20 09:11:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=5289 orders_uuids=2739
· 2021-12-20 09:16:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=5263 orders_uuids=2742
· 2021-12-20 09:21:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=3813 orders_uuids=2744
· 2021-12-20 09:26:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=2353 orders_uuids=2746
· 2021-12-20 09:31:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=4527 orders_uuids=2750
· 2021-12-20 09:36:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=2450 orders_uuids=2752
· 2021-12-20 09:41:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=1527 orders_uuids=2755
· 2021-12-20 09:46:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=3659 orders_uuids=2759
· 2021-12-20 09:51:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=1766 orders_uuids=2767
· 2021-12-20 09:56:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=3605 orders_uuids=2768
· 2021-12-20 10:01:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=2000 orders_uuids=2772
· 2021-12-20 10:06:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=3250 orders_uuids=2774
· 2021-12-20 10:11:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=4843 orders_uuids=2774
· 2021-12-20 10:16:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=5110 orders_uuids=2789
· 2021-12-20 10:21:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=5247 orders_uuids=2799
· 2021-12-20 10:26:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=5287 orders_uuids=2799
· 2021-12-20 10:31:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=5279 orders_uuids=2815
· 2021-12-20 10:36:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=5256 orders_uuids=2827
· 2021-12-20 10:41:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=2235 orders_uuids=2827
· 2021-12-20 10:46:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=3902 orders_uuids=2830
· 2021-12-20 10:51:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=2101 orders_uuids=2831
· 2021-12-20 10:56:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=3466 orders_uuids=2831
· 2021-12-20 11:01:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=4720 orders_uuids=2833
· 2021-12-20 11:06:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=1603 orders_uuids=2836
· 2021-12-20 11:11:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=3990 orders_uuids=2845
· 2021-12-20 11:16:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=4933 orders_uuids=2848
· 2021-12-20 11:21:12 +0000 [pubkey=031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8] history.commited_changes=5115 orders_uuids=2853

if this happens, i see orders double... i use setprice to set orders, which cancels previous orders from that pair, but this seems to not always happen like it should, so then i see 2 bids in the orderbook from that node instead of just one
strange is that both have the same "age": xxxxxxxx in the orderbook

i will run dev branch again for a while on one of the nodes and add the output from my_orders and the log file

[cipig]

collected infos... node was running for 1.5h, number of orders should be orders_uuids=1096, it was also the value it had before recompile and restart... seed node shows this:

· 2021-12-21 12:22:38 +0000 [pubkey=03de96cb66dcfaceaa8b3d4993ce8914cd5fe84e3fd53cefdae45add8032792a12] history.commited_changes=605 orders_uuids=1096
· 2021-12-21 12:27:38 +0000 [pubkey=03de96cb66dcfaceaa8b3d4993ce8914cd5fe84e3fd53cefdae45add8032792a12] history.commited_changes=1880 orders_uuids=1098
· 2021-12-21 12:32:38 +0000 [pubkey=03de96cb66dcfaceaa8b3d4993ce8914cd5fe84e3fd53cefdae45add8032792a12] history.commited_changes=629 orders_uuids=1098
· 2021-12-21 12:37:38 +0000 [pubkey=03de96cb66dcfaceaa8b3d4993ce8914cd5fe84e3fd53cefdae45add8032792a12] history.commited_changes=1915 orders_uuids=1098
· 2021-12-21 12:42:38 +0000 [pubkey=03de96cb66dcfaceaa8b3d4993ce8914cd5fe84e3fd53cefdae45add8032792a12] history.commited_changes=692 orders_uuids=1098
· 2021-12-21 12:47:38 +0000 [pubkey=03de96cb66dcfaceaa8b3d4993ce8914cd5fe84e3fd53cefdae45add8032792a12] history.commited_changes=1882 orders_uuids=1107
· 2021-12-21 12:52:38 +0000 [pubkey=03de96cb66dcfaceaa8b3d4993ce8914cd5fe84e3fd53cefdae45add8032792a12] history.commited_changes=1211 orders_uuids=1107
· 2021-12-21 12:57:38 +0000 [pubkey=03de96cb66dcfaceaa8b3d4993ce8914cd5fe84e3fd53cefdae45add8032792a12] history.commited_changes=884 orders_uuids=1107
· 2021-12-21 13:02:38 +0000 [pubkey=03de96cb66dcfaceaa8b3d4993ce8914cd5fe84e3fd53cefdae45add8032792a12] history.commited_changes=920 orders_uuids=1107
· 2021-12-21 13:07:38 +0000 [pubkey=03de96cb66dcfaceaa8b3d4993ce8914cd5fe84e3fd53cefdae45add8032792a12] history.commited_changes=530 orders_uuids=1107
· 2021-12-21 13:12:38 +0000 [pubkey=03de96cb66dcfaceaa8b3d4993ce8914cd5fe84e3fd53cefdae45add8032792a12] history.commited_changes=1396 orders_uuids=1107
· 2021-12-21 13:17:38 +0000 [pubkey=03de96cb66dcfaceaa8b3d4993ce8914cd5fe84e3fd53cefdae45add8032792a12] history.commited_changes=1184 orders_uuids=1108
· 2021-12-21 13:22:38 +0000 [pubkey=03de96cb66dcfaceaa8b3d4993ce8914cd5fe84e3fd53cefdae45add8032792a12] history.commited_changes=2013 orders_uuids=1108
· 2021-12-21 13:27:38 +0000 [pubkey=03de96cb66dcfaceaa8b3d4993ce8914cd5fe84e3fd53cefdae45add8032792a12] history.commited_changes=498 orders_uuids=1108
· 2021-12-21 13:32:38 +0000 [pubkey=03de96cb66dcfaceaa8b3d4993ce8914cd5fe84e3fd53cefdae45add8032792a12] history.commited_changes=1021 orders_uuids=1110
· 2021-12-21 13:37:38 +0000 [pubkey=03de96cb66dcfaceaa8b3d4993ce8914cd5fe84e3fd53cefdae45add8032792a12] history.commited_changes=1994 orders_uuids=1111
· 2021-12-21 13:42:38 +0000 [pubkey=03de96cb66dcfaceaa8b3d4993ce8914cd5fe84e3fd53cefdae45add8032792a12] history.commited_changes=481 orders_uuids=1112
· 2021-12-21 13:47:38 +0000 [pubkey=03de96cb66dcfaceaa8b3d4993ce8914cd5fe84e3fd53cefdae45add8032792a12] history.commited_changes=1754 orders_uuids=1113

output of my_orders:
my_orders.txt

log:
mm.log

prices are set with setprice every 4-8 minutes, there are 119 coins and 8 base coins, but not all have balance
i set one bid and one ask per pair

[shamardy]

A possible reason for this is that this continue https://github.com/KomodoPlatform/atomicDEX-API/blob/faf944ea721bd87816b9b3b1cdf02d4bf3f4c6ea/mm2src/lp_ordermatch.rs#L972 should be outside of the condition scope, I guess I missed this in the parking_lot PR. This makes the deleted order by the set_price request to be sometimes sent again here https://github.com/KomodoPlatform/atomicDEX-API/blob/faf944ea721bd87816b9b3b1cdf02d4bf3f4c6ea/mm2src/lp_ordermatch.rs#L980
What do you think @artemii235?

[cipig]

catched such a double order in BTCZ/JEUR-PLG20 orderbook:

{
  "askdepth": 0,
  "asks": [
    {
      "coin": "BTCZ",
      "address": "t1bjmkBWkzLWk3mHFoybXE5daGRY9pk1fxF",
      "price": "0.0003320156",
      "maxvolume": "142175.836249834",
      "min_volume": "0.003011906669445652553675188756190974159045538824079350488350547383918105052895104928804550147643664936",
      "pubkey": "031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8",
      "age": 1640281686,
      "zcredits": 0,
      "uuid": "c7739424-2487-4983-8d09-20a70e2527fd",
      "is_mine": false,
      "base_max_volume": "142175.836249834",
      "base_min_volume": "0.003011906669445652553675188756190974159045538824079350488350547383918105052895104928804550147643664936",
      "rel_max_volume": "47.2045955779903854104",
      "rel_min_volume": "0.000001",
      "base_max_volume_aggr": "284611.369927292",
      "rel_max_volume_aggr": "94.3880468479457419148"
    },
    {
      "coin": "BTCZ",
      "address": "t1bjmkBWkzLWk3mHFoybXE5daGRY9pk1fxF",
      "price": "0.0003312618",
      "maxvolume": "142435.533677458",
      "min_volume": "0.003018760388309186268987248152367704335362544066354768343346561541354904187564035454737008613730892001",
      "pubkey": "031bb83b58ec130e28e0a6d5d2acf2eb01b0d3f1670e021d47d31db8a858219da8",
      "age": 1640281686,
      "zcredits": 0,
      "uuid": "b6432b44-0b1c-4c75-924c-f12a35b3df10",
      "is_mine": false,
      "base_max_volume": "142435.533677458",
      "base_min_volume": "0.003018760388309186268987248152367704335362544066354768343346561541354904187564035454737008613730892001",
      "rel_max_volume": "47.1834512699553565044",
      "rel_min_volume": "0.000001",
      "base_max_volume_aggr": "142435.533677458",
      "rel_max_volume_aggr": "47.1834512699553565044"
    }
  ],

there are 2 asks from the same pubkey, there should be only one
b6432b44-0b1c-4c75-924c-f12a35b3df10 is not in my_orders output, c7739424-2487-4983-8d09-20a70e2527fd is
but both orders show up on other nodes

[artemii235]

@shamardy

A possible reason for this is that this continue
What do you think artemii235?

If you notice that you can fix a bug please feel free to work on it without explicit approval in the future. We can discuss the details after you open a PR.

[artemii235]

@shamardy

A possible reason for this is that this continue

maker_order_updated_p2p_notify message doesn't lead to the order being recreated on other nodes, it's ignored if the order doesn't exist assuming that it will be synced upon next pubkey keep alive processing:

https://github.com/KomodoPlatform/atomicDEX-API/blob/bf249e0db9be9b9e1c32012e03ee490e0af47e93/mm2src/lp_ordermatch.rs#L282-L288

The reason is most likely in another place, in lp_ordermatch_loop we check that maker order is not added to orderbook, which was the case only after kickstart previously. As of now, the order might be canceled between the following lines, and MM2 will notify other nodes about the non-existent record:

https://github.com/KomodoPlatform/atomicDEX-API/blob/bf249e0db9be9b9e1c32012e03ee490e0af47e93/mm2src/lp_ordermatch.rs#L2828-L2832

I guess it's more likely to happen with a big number of orders per node.

@cipig Could you please check if the problem is fixed in the https://github.com/KomodoPlatform/atomicDEX-API/tree/orderbook_fixes?

[cipig]

thanks, problem fixed
all 4 nodes have a stable number of orders