Bug: occasionally bogus response for mempool.get_fee_histogram()

[Overtorment]

i was debugging unsusually high fees, and discovered that Fulcrum electrum server run by Foundationdevices occasionally returns bogus fee histogram, which leads to unusually high fees for the clients:

    connected to  [ 'Fulcrum 1.9.1', '1.4' ]

      at console.apply [as log] (tests/setup.js:22:18)

  console.log
    histogram= [
      [ 27889368, 101334 ],  [ 22845567, 126781 ],  [ 22724691, 137840 ],
      [ 22602555, 98280 ],   [ 22486736, 308841 ],  [ 22486735, 1719 ],
      [ 22369618, 421512 ],  [ 22369617, 1728 ],    [ 22024184, 159997 ],
      [ 20069875, 235780 ],  [ 19884105, 366226 ],  [ 19346694, 238874 ],
      [ 19259937, 261092 ],  [ 19088738, 451976 ],  [ 19004274, 274935 ],
      [ 17179864, 434607 ],  [ 15561473, 449891 ],  [ 14081858, 547996 ],
      [ 13944697, 515903 ],  [ 13721939, 1227255 ], [ 13721938, 829450 ],
      [ 13721867, 313 ],     [ 13463845, 1199234 ], [ 13421771, 7720317 ],
      [ 13421770, 20800 ],   [ 13421769, 4480 ],    [ 13421765, 320 ],
      [ 13421757, 320 ],     [ 13421741, 640 ],     [ 13379958, 756597 ],
      [ 13215282, 7425741 ], [ 13215281, 650 ],     [ 13215253, 325 ],
      [ 12897798, 360093 ],  [ 3193267, 2501946 ],  [ 1370390, 2730720 ],
      [ 396687, 3096242 ],   [ 288516, 3395060 ],   [ 248451, 3750431 ],
      [ 160228, 4316793 ],   [ 99977, 4314072 ],    [ 55966, 4982554 ],
      [ 49591, 5686498 ],    [ 43265, 5812345 ],    [ 30778, 6675799 ],
      [ 27135, 7378403 ],    [ 5, 7945524 ],        [ 2, 19948231 ],
      [ 1, 41450679 ],       [ 0, 14506158 ]
    ]

this is reproduceable occasionally (maybe its this specific server issue..?), and adequate response looks like this (that was run few minutes apart):

  console.log
    connected to  [ 'Fulcrum 1.9.1', '1.4' ]

      at console.apply [as log] (tests/setup.js:22:18)

  console.log
    histogram= [
      [ 26, 101159 ],
      [ 18, 130187 ],
      [ 15, 120294 ],
      [ 12, 118992 ],
      [ 8, 164375 ],
      [ 6, 151477 ],
      [ 4, 1854539 ],
      [ 3, 7935283 ],
      [ 2, 32246458 ],
      [ 1, 78272068 ],
      [ 0, 37831422 ]
    ]


      at console.apply [as log] (tests/setup.js:22:18)

  console.log
    { fast: 8, medium: 6, slow: 4 }

[Overtorment]

the simplest reproduce via cli:

ghost@aaa ~/Documents/BlueWallet (master) $ echo '{"id": 1, "method": "mempool.get_fee_histogram"}' | timeout 2 openssl s_client -quiet  -connect mainnet.foundationdevices.com:50002 2>/dev/null
{"id":1,"jsonrpc":"2.0","result":[[27889368,100881],[22845567,126619],[22724691,137840],[22600154,98850],[22486736,308271],[22486735,1719],[22369618,421321],[22369617,1728],[22023025,160777],[20069870,235856],[19884105,365156],[19346694,238659],[19259937,261092],[19088738,451530],[19004274,274935],[17179864,433889],[15561473,449891],[14081858,547996],[13944697,514368],[13721939,1227255],[13721938,826320],[13721867,313],[13463845,1199234],[13421771,7720317],[13421770,20800],[13421769,4480],[13421765,320],[13421757,320],[13421741,640],[13379958,756597],[13215282,7425741],[13215281,650],[13215253,325],[12897798,360093],[3179089,2429899],[1075353,2808101],[378110,3091556],[286695,3403828],[247651,3750236],[147806,4118023],[89953,4523492],[49660,5003589],[49577,5560166],[42737,5942062],[30447,6640875],[25266,7314508],[3,12497731],[2,12454954],[1,41262532],[0,14505752]]}
ghost@aaa ~/Documents/BlueWallet (master) $ date
Thu 28 Sep 2023 04:33:08 PM BST
ghost@aaa ~/Documents/BlueWallet (master) $ echo '{"id": 1, "method": "mempool.get_fee_histogram"}' | timeout 2 openssl s_client -quiet  -connect mainnet.foundationdevices.com:50002 2>/dev/null
{"id":1,"jsonrpc":"2.0","result":[[41,100873],[26,139494],[23,102018],[20,130427],[17,206945],[16,139543],[14,197296],[12,208098],[10,220605],[7,228755],[6,239697],[4,2103924],[3,8113006],[2,32246863],[1,77769095],[0,37829703]]}
ghost@aaa ~/Documents/BlueWallet (master) $ date
Thu 28 Sep 2023 04:33:13 PM BST

[cculianu]

You're probably right there may be a bug. I'm looking at the code in Fulcrum and comparing it to ElectrumX: https://github.com/spesmilo/electrumx/blob/bbd985a95db63cada13254bb766f174e9ab674d0/electrumx/server/mempool.py#L154. I tried to just emulate their algorithm but I see they have since updated it.

I will work on porting over the new changes to the algorithm.

[cculianu]

Ok, I pushed this commit: 1ad892d -- this should address the issue.

Note that I am traveling and thus may not be able to do a new release anytime soon to fix this. :/

Is there any way you can build Fulcrum yourself against master and test this and provide feedback that the issue is indeed solve? I was unable to reproduce because I don't have my server online right now.

[cculianu]

Ok well, 3 things:

1. I am indeed preparing a release now including the code changes I did.
2. I am seeing the bad fees on that server but I can't for the life of me figure out how Fulcrum could end up with such bogus fees. Has this been seen in the wild on any other server? My server here is fine, no issue.
3. Hopefully my latest release will magically fix it. I just synched my code more closely with ElectrumX for this particular facility.

[cculianu]

.. it's also possible this is not a Fulcrum issue at all but rather the server itself is griefing its users for some reason or other (there are incentives to do this, of course, if one is also a miner).

[Overtorment]

Yeah it's weird that the same server can return normal and faulty fees in consecutive requests. Probably need to reach out to Foundationdevices to investigate

[nickmonad]

Hey, I run the fulcrum node at Foundation. This is indeed an odd situation. I want to reassure anybody coming across this issue that we are not involved in manipulating the fees reported by our nodes in any way. We don't mine or encourage our users to pay high fees unnecessarily. The reason we haven't seen this issue in the past is because we don't use fulcrum to report fees to our Envoy users, but rather mempool.space

Some notes about our setup: we run two load-balanced fulcrum servers based on a "least connections" selection. We do this so we can safely update without downtime for our users by shifting traffic to one of the nodes, upgrading the other, and repeating that process until both are updated. So, maybe the weirdness seen where consecutive requests will return different results is due to that fact? Another thing is that we run our config with peering=false - not sure if that is relevant or not.

Anyway, apologies for the issues on our end. I will upgrade to 1.9.2 today, and hopefully that resolves the issue.

[cculianu]

@nickmonad Thanks for chiming in with more info on the issue. Sorry for insinuating it might be intentional on your part -- it's just such a mystery is all! I believe you that you aren't involved in manipulating fees and who knows maybe it is some esoteric bug. I do hope that the new code and the new setup will mean everything is resolved. Thanks for responding and being informative and helpful!

[nickmonad]

@cculianu All good, thanks for cutting a new release with a possible fix.

@Overtorment I ran your mempool.get_fee_histogram commands above on our updated servers and it seems to report consistent, expected results?

[cculianu]

Well since I haven't heard any complaints about this continuing to happen.. will close this issue. If it happens can re-open.