v24.08.2 BROKEN bookeeper plugin

[darioAnongba]

When updating from v24.05 to v24.08.2, the update fails with the following logs:

Core-Lightning starting
2024-10-22T17:12:18.465Z INFO    lightningd: v24.08.2
...
2024-10-22T17:12:19.422Z UNUSUAL plugin-bookkeeper: topic 'utxo_deposit' is not a known notification topic
2024-10-22T17:12:19.422Z UNUSUAL plugin-bookkeeper: topic 'utxo_spend' is not a known notification topic
2024-10-22T17:12:25.445Z DEBUG   plugin-clnrest: REST Server is starting at https://0.0.0.0:3010
2024-10-22T17:12:25.446Z DEBUG   plugin-clnrest: Certs Path: /root/.lightning/bitcoin
2024-10-22T17:12:25.455Z DEBUG   lightningd: Looking for [autoclean,failedforwards,num]
2024-10-22T17:12:25.460Z INFO    plugin-clnrest: REST server running at https://0.0.0.0:3010
2024-10-22T17:12:25.464Z DEBUG   lightningd: Looking for [autoclean,succeededpays,num]
Error executing statement: ERROR:  current transaction is aborted, commands ignored until end of transaction block
bookkeeper: Outstanding taken pointers: 0x5606eceb0a88
2024-10-22T17:12:25.483Z DEBUG   lightningd: Looking for [autoclean,failedpays,num]
2024-10-22T17:12:25.484Z DEBUG   hsmd: Client: Received message 27 from client
2024-10-22T17:12:25.492Z INFO    plugin-bookkeeper: Killing plugin: exited before replying to init
2024-10-22T17:12:25.492Z **BROKEN** plugin-bookkeeper: Plugin marked as important, shutting down lightningd!
2024-10-22T17:12:25.492Z DEBUG   lightningd: io_break: lightningd_exit
2024-10-22T17:12:25.501Z DEBUG   plugin-recover: Recover Plugin Initialised!
...
2024-10-22T17:12:25.573Z DEBUG   lightningd: Looking for [autoclean,expiredinvoices,num]
2024-10-22T17:12:55.528Z DEBUG   lightningd: clnrest: failed to self-terminate in time, killing.
2024-10-22T17:12:55.528Z DEBUG   lightningd: io_break: destroy_plugin
2024-10-22T17:12:55.528Z DEBUG   connectd: Shutting down
2024-10-22T17:12:55.529Z DEBUG   gossipd: Shutting down
2024-10-22T17:12:55.531Z DEBUG   hsmd: Shutting down
Reading JSON input: Connection reset by peerReading JSON input: Connection reset by peerReading JSON input: Connection reset by peerReading JSON input: Connection reset by peerReading JSON input: Connection reset by peerReading JSON input: Connection reset by peer

We somewhat have a special config as we are using Postgres as DB. Any idea what might be the issue ?

Reverting to v24.05(-modded) makes it work again so it's not a question of permissions to access the DB I think.

[hMsats]

Confirm this for v24.08.2:

2024-10-18T19:42:31.152Z INFO    lightningd: v24.08.2
2024-10-18T19:42:40.742Z UNUSUAL plugin-bookkeeper: topic 'utxo_deposit' is not a known notification topic
2024-10-18T19:42:40.742Z UNUSUAL plugin-bookkeeper: topic 'utxo_spend' is not a known notification topic

and I have a standard config

[svpi11]

Same here...

[ron-slc]

I was able to resolve this in v24.11.1(-modded) by installing the APT packages, and Python PIPs as required by clnrest. I'm running Debian 12/Bookworm, with one deviation; I have pulled in restc and it's required depends from Debian 13/Trixie/Testing - this is only a compile-time requirement for building newer CLN versions.

apt-get install python3-json5 python3-flask python3-gunicorn python3-gevent-websocket python3-flask-socketio python3-flask-cors
pip3 install --user flask-restx pyln-client

• The above apt-get and pip3 install commands also worked on my Debian 11/Bullseye node.

It's very strange the daemon is exiting without a real explanation, or stack trace, given this boiled down to a missing dependency. So IMO, there is a missing BROKEN logging output for missing+required Python3 packages.

The log entries on a successful launch, to show the difference:

2025-01-10T16:10:33.627Z DEBUG   plugin-manager: started(26962) /usr/local/libexec/c-lightning/plugins/bookkeeper
2025-01-10T16:10:33.638Z DEBUG   plugin-manager: started(26970) /usr/local/libexec/c-lightning/plugins/clnrest/clnrest
2025-01-10T16:10:33.654Z DEBUG   plugin-manager: started(26975) /usr/local/libexec/c-lightning/plugins/wss-proxy/wss-proxy
2025-01-10T16:10:33.702Z INFO    plugin-wss-proxy: Killing plugin: disabled itself: No module named 'websockets'
2025-01-10T16:10:35.230Z UNUSUAL plugin-bookkeeper: topic 'utxo_deposit' is not a known notification topic
2025-01-10T16:10:35.230Z UNUSUAL plugin-bookkeeper: topic 'utxo_spend' is not a known notification topic
2025-01-10T16:10:35.230Z DEBUG   lightningd: io_break: check_plugins_manifests
2025-01-10T16:10:35.230Z DEBUG   lightningd: io_loop_with_timers: plugins_init
 *** THIS IS WHERE 'lightningd' WOULD PREVIOUSLY EXIT ***
2025-01-10T16:10:35.236Z DEBUG   lightningd: testing /usr/local/bin/../libexec/c-lightning/lightning_channeld
2025-01-10T16:10:35.246Z DEBUG   lightningd: testing /usr/local/bin/../libexec/c-lightning/lightning_closingd
2025-01-10T16:10:35.255Z DEBUG   lightningd: testing /usr/local/bin/../libexec/c-lightning/lightning_connectd
... logs continue as expected from here ...

[darioAnongba]

Little update here. I was never able to fix this issue but simply removing the config:
bookkeeper-db seems to do the trick. The migration on postgres fails but works on SQLite. It is not really important for us to use Postgres for the bookkeeping plugin anyways but the data will be lost when we migrate the node to some other persistence.