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

plugin: notify only the plugins with init state #7277

Merged

Conversation

vincenzopalazzo
Copy link
Contributor

This is fixing a bug that @chrisguida reported,
when we notify a plugin we also notify a plugin
that it is in the middle of initialization.

So imagine the following use case:

    1. Plugin A sends get manifest
    1. cln makes a check and generates a warning
    1. Plugin A is subscribed to the warning or * notification
    1. Core Lightning gets upset because it receives a warning message but it was waiting for a init.

I think it is still a bug in how Core Lightning handles the init, but also I think we should communicate with the plugin only if it is initialized.

lightningd-1 2024-04-23T23:20:34.154Z DEBUG   plugin-clnrest: Notification: {'warning': {'level': 'warn', 'time': '1713914433.818230531', 'timestamp': '2024-04-23T23:20:33.818Z', 'source': 'plugin-bookkeeper', 'log': \"topic 'utxo_deposit' is not a known notification topic\"}}
lightningd-1 2024-04-23T23:20:34.154Z DEBUG   hsmd: new_client: 0
lightningd-1 2024-04-23T23:20:34.154Z **BROKEN** plugin-test_libplugin: Did not receive 'init' yet, but got 'warning' instead
lightningd-1 2024-04-23T23:20:34.155Z INFO    plugin-test_libplugin: Killing plugin: exited before we sent init
lightningd-1 2024-04-23T23:20:34.155Z **BROKEN** plugin-test_libplugin: Plugin marked as important, shutting down lightningd!
lightningd-1 2024-04-23T23:20:34.155Z DEBUG   lightningd: io_break: lightningd_exit
lightningd-1 2024-04-23T23:20:34.155Z DEBUG   lightningd: io_loop: connectd_init
Time-out: can't find [re.compile('Server started with public key')] in logs
{'github_repository': 'ElementsProject/lightning', 'github_sha': '014c1eb383b0a65394cf166b3aa0174cf2077896', 'github_ref': 'refs/pull/7258/merge', 'github_ref_name': 'HEAD', 'github_run_id': 8808124001, 'github_head_ref': 'cguida/onchain_notif', 'github_run_number': 9395, 'github_base_ref': 'master', 'github_run_attempt': '1', 'testname': 'test_self_disable', 'start_time': 1713914432, 'end_time': 1713914612, 'outcome': 'fail'}
----------------------------- Captured stderr call -----------------------------
Did not receive 'init' yet, but got 'warning' insteadlightningd: lightningd/connect_control.c:767: connectd_init: Assertion `ret == ld->connectd' failed.
lightningd: FATAL SIGNAL 6 (version 014c1eb-modded)
0x555b1dc2d6f3 send_backtrace
	common/daemon.c:33
0x555b1dc2d8de crashdump
	common/daemon.c:75
0x7fda4584251f ???
	???:0
0x7fda458969fc ???
	???:0
0x7fda45842475 ???
	???:0
0x7fda458287f2 ???
	???:0
0x7fda4582871a ???
	???:0
0x7fda45839e95 ???
	???:0
0x555b1db98f8e connectd_init
	lightningd/connect_control.c:767
0x555b1dbb0307 main
	lightningd/lightningd.c:1249
0x7fda45829d8f ???
	???:0
0x7fda45829e3f ???
	???:0
0x555b1db6fd64 ???
	???:0
0xffffffffffffffff ???
	???:0

This is fixing a bug that @chrisguida reported,
when we notify a plugin we also notify a plugin
that it is in the middle of initialization.

So imagine the following use case:

- 1. Plugin A sends get manifest
- 2. cln makes a check and generates a warning
- 3. Plugin A is subscribed to the warning or * notification
- 4. Core Lightning gets upset because it receives a warning message but it was waiting for a init.

I think it is still a bug in how Core Lightning handles the init, but also I think we should communicate with the plugin only if it is initialized.

```
lightningd-1 2024-04-23T23:20:34.154Z DEBUG   plugin-clnrest: Notification: {'warning': {'level': 'warn', 'time': '1713914433.818230531', 'timestamp': '2024-04-23T23:20:33.818Z', 'source': 'plugin-bookkeeper', 'log': \"topic 'utxo_deposit' is not a known notification topic\"}}
lightningd-1 2024-04-23T23:20:34.154Z DEBUG   hsmd: new_client: 0
lightningd-1 2024-04-23T23:20:34.154Z **BROKEN** plugin-test_libplugin: Did not receive 'init' yet, but got 'warning' instead
lightningd-1 2024-04-23T23:20:34.155Z INFO    plugin-test_libplugin: Killing plugin: exited before we sent init
lightningd-1 2024-04-23T23:20:34.155Z **BROKEN** plugin-test_libplugin: Plugin marked as important, shutting down lightningd!
lightningd-1 2024-04-23T23:20:34.155Z DEBUG   lightningd: io_break: lightningd_exit
lightningd-1 2024-04-23T23:20:34.155Z DEBUG   lightningd: io_loop: connectd_init
Time-out: can't find [re.compile('Server started with public key')] in logs
{'github_repository': 'ElementsProject/lightning', 'github_sha': '014c1eb383b0a65394cf166b3aa0174cf2077896', 'github_ref': 'refs/pull/7258/merge', 'github_ref_name': 'HEAD', 'github_run_id': 8808124001, 'github_head_ref': 'cguida/onchain_notif', 'github_run_number': 9395, 'github_base_ref': 'master', 'github_run_attempt': '1', 'testname': 'test_self_disable', 'start_time': 1713914432, 'end_time': 1713914612, 'outcome': 'fail'}
----------------------------- Captured stderr call -----------------------------
Did not receive 'init' yet, but got 'warning' insteadlightningd: lightningd/connect_control.c:767: connectd_init: Assertion `ret == ld->connectd' failed.
lightningd: FATAL SIGNAL 6 (version 014c1eb-modded)
0x555b1dc2d6f3 send_backtrace
	common/daemon.c:33
0x555b1dc2d8de crashdump
	common/daemon.c:75
0x7fda4584251f ???
	???:0
0x7fda458969fc ???
	???:0
0x7fda45842475 ???
	???:0
0x7fda458287f2 ???
	???:0
0x7fda4582871a ???
	???:0
0x7fda45839e95 ???
	???:0
0x555b1db98f8e connectd_init
	lightningd/connect_control.c:767
0x555b1dbb0307 main
	lightningd/lightningd.c:1249
0x7fda45829d8f ???
	???:0
0x7fda45829e3f ???
	???:0
0x555b1db6fd64 ???
	???:0
0xffffffffffffffff ???
	???:0
```

Reported-by: @chrisguida
Co-Developed-by: @chrisguida
Signed-off-by: Vincenzo Palazzo <[email protected]>
@endothermicdev
Copy link
Collaborator

Nice catch. Maybe we could also validate this alongside test_plugin.py::test_warning_notification or test_all_subscription.

@rustyrussell rustyrussell merged commit e8372e7 into ElementsProject:master May 9, 2024
34 of 35 checks passed
@vincenzopalazzo vincenzopalazzo deleted the macros/fix-log branch May 9, 2024 05:33
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants