rebalance plugin crashes

[thestick613]

2021-01-23T23:44:33.003Z INFO    plugin-rebalance.py: Plugin rebalance initialized with 1000msat base / 10 ppm fee, cltv_final: 18
2021-01-23T23:45:35.890Z UNUSUAL plugin-rebalance.py: Exception in thread Thread-1:
2021-01-23T23:45:35.890Z UNUSUAL plugin-rebalance.py: Traceback (most recent call last):
2021-01-23T23:45:35.891Z UNUSUAL plugin-rebalance.py:   File \"/usr/lib/python3.8/threading.py\", line 932, in _bootstrap_inner
2021-01-23T23:45:35.897Z UNUSUAL plugin-rebalance.py:     self.run()
2021-01-23T23:45:35.898Z UNUSUAL plugin-rebalance.py:   File \"/usr/lib/python3.8/threading.py\", line 870, in run
2021-01-23T23:45:35.898Z UNUSUAL plugin-rebalance.py:     self._target(*self._args, **self._kwargs)
2021-01-23T23:45:35.898Z UNUSUAL plugin-rebalance.py:   File \"/home/user/plugins/rebalance/rebalance.py\", line 433, in rebalanceall_thread
2021-01-23T23:45:35.899Z UNUSUAL plugin-rebalance.py:     plugin.ideal_ratio = get_ideal_ratio(channels, plugin.enough_liquidity)
2021-01-23T23:45:35.899Z UNUSUAL plugin-rebalance.py:   File \"/home/user/plugins/rebalance/rebalance.py\", line 304, in get_ideal_ratio
2021-01-23T23:45:35.900Z UNUSUAL plugin-rebalance.py:     if smallest_channel[\"total_msat\"] * min(ratio, 1 - ratio) > enough_liquidity:
2021-01-23T23:45:35.900Z UNUSUAL plugin-rebalance.py:   File \"/usr/local/lib/python3.8/dist-packages/pyln/client/lightning.py\", line 180, in __mul__
2021-01-23T23:45:35.901Z UNUSUAL plugin-rebalance.py:     return Millisatoshi(self.millisatoshis * other)
2021-01-23T23:45:35.901Z UNUSUAL plugin-rebalance.py:   File \"/usr/local/lib/python3.8/dist-packages/pyln/client/lightning.py\", line 72, in __init__
2021-01-23T23:45:35.901Z UNUSUAL plugin-rebalance.py:     raise TypeError(
2021-01-23T23:45:35.901Z UNUSUAL plugin-rebalance.py: TypeError: Millisatoshi must be string with msat/sat/btc suffix or int

pinging @m-schmoock

[m-schmoock]

@thestick613 Hi, this is likely related to an already fixed issue in pyln-client. See main repo commit: https://github.com/ElementsProject/lightning/commit/565dc95a8 . This should work with a recent pyln-client lib. Please check ...

[thestick613]

I checked and i'm running Requirement already up-to-date: pyln-client in /usr/local/lib/python3.8/dist-packages (0.9.2) Which was released after that fix.

[cdecker]

Nope, the fix was included in 0.9.3 which I haven't published to pypi yet 🤦 Will do that asap and then we can bump the requirement to pyln-client==0.9.3

[aido]

Hi,

Seeing issues with rebalance plugin also:

2021-02-01T03:05:50.590Z UNUSUAL plugin-rebalance.py: Exception in thread Thread-1:
2021-02-01T03:05:50.591Z UNUSUAL plugin-rebalance.py: Traceback (most recent call last):
2021-02-01T03:05:50.591Z UNUSUAL plugin-rebalance.py:   File \"/usr/lib/python3.9/threading.py\", line 954, in _bootstrap_inner
2021-02-01T03:05:50.611Z UNUSUAL plugin-rebalance.py:     self.run()
2021-02-01T03:05:50.611Z UNUSUAL plugin-rebalance.py:   File \"/usr/lib/python3.9/threading.py\", line 892, in run
2021-02-01T03:05:50.613Z UNUSUAL plugin-rebalance.py:     self._target(*self._args, **self._kwargs)
2021-02-01T03:05:50.614Z UNUSUAL plugin-rebalance.py:   File \"/usr/libexec/c-lightning/plugins/rebalance/rebalance.py\", line 433, in rebalanceall_thread
2021-02-01T03:05:50.615Z UNUSUAL plugin-rebalance.py:     plugin.ideal_ratio = get_ideal_ratio(channels, plugin.enough_liquidity)
2021-02-01T03:05:50.615Z UNUSUAL plugin-rebalance.py:   File \"/usr/libexec/c-lightning/plugins/rebalance/rebalance.py\", line 302, in get_ideal_ratio
2021-02-01T03:05:50.617Z UNUSUAL plugin-rebalance.py:     ratio = int(our) / int(total)
2021-02-01T03:05:50.617Z UNUSUAL plugin-rebalance.py: ZeroDivisionError: division by zero

aido@lightning:~# /usr/bin/lightning-cli --version
v0.9.3rc2-4-g015ac37-modded
aido@lightning:~# pip3 freeze | grep pyln
pyln-client==0.9.3
pyln-proto==0.9.3

Should https://github.com/lightningd/plugins/blob/abbdeabec6504b1f1771473296b7656f53293723/rebalance/rebalance.py#L298-L299 be:

    our = sum(ch["msatoshi_to_us"] for ch in channels)
    total = sum(ch["msatoshi_total"] for ch in channels)

?

[m-schmoock]

@aido No, using the _msat fields is correct and better. However you discovered that get_ideal_ratio can get called with an empty channels list which will result to the division by zero error. I will open up a PR...

[aido]

thanks @m-schmoock

hmmm, now you make me question why plugin thinks my channel list is empty as in my test I have several open channels in CHANNELD_NORMAL state and with non-zero values in to_us_msat and total_msat.

[m-schmoock]

@aido

hmmm, now you make me question why plugin thinks my channel list is empty as in my test I have several open channels in CHANNELD_NORMAL state and with non-zero values in to_us_msat and total_msat.

I thought that this would have been the case. Can you retry/test with #211 applied?

[m-schmoock]

@aido

1. Can you send me a private gist or something of the listpeers output? (if you don't mind)
2. Am I right this div by zero happens when you try to use rebalanceall?

[aido]

Hi @m-schmoock

The assert you added in #211 is now confirming that channel list is not empty but I still get a divide by zero error when I try to use rebalanceall:

2021-02-01T12:09:03.219Z UNUSUAL plugin-rebalance.py: Exception in thread Thread-1:
2021-02-01T12:09:03.220Z UNUSUAL plugin-rebalance.py: Traceback (most recent call last):
2021-02-01T12:09:03.220Z UNUSUAL plugin-rebalance.py:   File \"/usr/lib/python3.9/threading.py\", line 954, in _bootstrap_inner
2021-02-01T12:09:03.238Z UNUSUAL plugin-rebalance.py:     self.run()
2021-02-01T12:09:03.238Z UNUSUAL plugin-rebalance.py:   File \"/usr/lib/python3.9/threading.py\", line 892, in run
2021-02-01T12:09:03.241Z UNUSUAL plugin-rebalance.py:     self._target(*self._args, **self._kwargs)
2021-02-01T12:09:03.241Z UNUSUAL plugin-rebalance.py:   File \"/usr/libexec/c-lightning/plugins/rebalance/rebalance.py\", line 434, in rebalanceall_thread
2021-02-01T12:09:03.242Z UNUSUAL plugin-rebalance.py:     plugin.ideal_ratio = get_ideal_ratio(channels, plugin.enough_liquidity)
2021-02-01T12:09:03.243Z UNUSUAL plugin-rebalance.py:   File \"/usr/libexec/c-lightning/plugins/rebalance/rebalance.py\", line 303, in get_ideal_ratio
2021-02-01T12:09:03.244Z UNUSUAL plugin-rebalance.py:     ratio = int(our) / int(total)
2021-02-01T12:09:03.244Z UNUSUAL plugin-rebalance.py: ZeroDivisionError: division by zero

Will send you private gist of listpeers, thanks.

[m-schmoock]

That is indeed really strange :D I will figure it out. Thanks.

[aido]

Hi @m-schmoock

There is an infinite loop that removes objects from a list until there are zero objects left resulting in a division by zero error.. By changing:

https://github.com/lightningd/plugins/blob/abbdeabec6504b1f1771473296b7656f53293723/rebalance/rebalance.py#L301

to

   while len(chs) > 0:

ensures the loop stops before the list is empty.

This fixes the divide by zero error but now the following result needs investigation:

2021-02-01T23:10:55.893Z INFO    plugin-rebalance.py: Automatic rebalance is running with enough liquidity threshold: 0msat, ideal liquidity ratio: 100.00%, min rebalancable amount: 50000000msat, feeratio: 0.5
2021-02-01T23:10:56.130Z INFO    plugin-feeadjuster.py: 0 channels adjusted
2021-02-01T23:10:56.132Z INFO    plugin-rebalance.py: Feeadjust succeeded: 0 channels adjusted
2021-02-01T23:10:56.149Z INFO    plugin-rebalance.py: Automatic rebalance finished: 0 successful rebalance, 0msat fee spent, it took 0:00:00.346

[aido]

Hi @m-schmoock

When a new lightning node is started and channels intially created and funded all funds could be on our side so that our funds and total funds in all channels may be the same i.e. total == our. This condition may cause some of the logic in rebalanceall to break down.

The check_liquidity_threshold function is as follows: https://github.com/lightningd/plugins/blob/4a9df896ad2690924af4df8db82f86f19114ebba/rebalance/rebalance.py#L268-L275

If total and our are equal then the required < total - our condition reults in check_liquidity_threshold always returning 0. This in turn results in max_threshold always being 0msat.

This may be fixed by changing the following: https://github.com/lightningd/plugins/blob/4a9df896ad2690924af4df8db82f86f19114ebba/rebalance/rebalance.py#L275

to

    return required < our and (required < total - our or total == our)

That's one problem in this case but there is another......

[m-schmoock]

Thanks. I'm on it, rewriting and TESTING some stuff.. :D

[aido]

@m-schmoock

Great!

Another thing I see in the case where total == our is that in the get_ideal_ratio function ratio is >1 which is causing :

ValueError: Millisatoshi must be >= 0

at line: https://github.com/lightningd/plugins/blob/4a9df896ad2690924af4df8db82f86f19114ebba/rebalance/rebalance.py#L304

Currently investigating why this is.

[m-schmoock]

Hi

ValueError: Millisatoshi must be >= 0

Do you have a stack trace for this?

Also for the mentioned potential bugs, I couldn't trigger them with the testcase I commited in PR #211 I added two of your fixes because they seemed safer to me. Ideally we can construct testcases that trigger the mentioned issues...

[m-schmoock]

@aido I just merged https://github.com/lightningd/plugins/pull/211 . Can you retry with this changeset. If you still have remaining issues, can you try to construct testcases that cover this? Because the our == total is now covered by test_rebalance_all and its not causing the issues you describe (which is why I did not take all of your suggestions).

[m-schmoock]

@aido

This fixes the divide by zero error but now the following result needs investigation:

2021-02-01T23:10:55.893Z INFO    plugin-rebalance.py: Automatic rebalance is running with enough liquidity threshold: 0msat, ideal liquidity ratio: 100.00%, min rebalancable amount: 50000000msat, feeratio: 0.5
2021-02-01T23:10:56.130Z INFO    plugin-feeadjuster.py: 0 channels adjusted
2021-02-01T23:10:56.132Z INFO    plugin-rebalance.py: Feeadjust succeeded: 0 channels adjusted
2021-02-01T23:10:56.149Z INFO    plugin-rebalance.py: Automatic rebalance finished: 0 successful rebalance, 0msat fee spent, it took 0:00:00.346

I successfully reproduced your situation with the data you send me. As I see it you have 15 channels where you have 100% of the balance for all channels. This is a quite distorted situation. The rebalance plugin is not able to balance anything in this case, because when it sends out money it also needs to be able to receive on another channel, which is not possible as you dont have any incoming capacity.

What we could to is to add an early check for this and return an error on calling rebalanceall. Not sure how useful this is.

If you want incoming liquidity, just ask me ;)

TLDR: This is expected behaviour in your situation

[aido]

Hi @m-schmoock

I have tested #211 and no longer get divide by zero errors.

Your analysis of my distorted situaton is correct. I now need to figure out how to get myself out of the catch 22 situation I find my channels in :-)

[m-schmoock]

Okay, we can close now... If you need incoming liquidity, just ask i.e. in irc.freenode.org #c-lightning