[Bug] When using -plugindir, plugins get stuck in initialization

[NicolasDorier]

This is continuation of #4810

Our users in btcpay had their c-lightning not working anymore after adding plugins with -plugindir. Reverting it (btcpayserver/btcpayserver-docker@33fd9d2) fixed the situation.

I tried to printf debug it, and I found out that even bcli, which is not even a plugin in the plugindir was blocked on initialization.
The init of the plugin was called, but the plugin couldn't even report back logs about what was going on.

I also tried to remove our only plugin in plugindir (invoicewithdescriptionhash), but this didn't fix the situation.

Let me know if I can assist more for debugging this. I can repro easily now.

[cdecker]

My current working theory is that we're blocking on one of the plugins in the plugindir, since we iterate through them in dependency order, and doing so sequentially. The only thing that comes to mind that is out of the ordinary in docker volumes are permissions, so this could be a non-plugin being treated as a plugin due to a permission mixup.

@NicolasDorier can you list the files in the plugin directory, and can you tell us more about the volume (host OS, underlying filesystem, ...)?

[NicolasDorier]

So I tried to revert the commit. Could repro the problem.

My plugindir is empty.

root@btcpay763334:~/btcpayserver-docker# docker exec btcpayserver_clightning_bitcoin ls -al /etc/clightningplugins
total 8
drwxr-xr-x 2 root root 4096 Sep 28 02:06 .
drwxr-xr-x 1 root root 4096 Sep 28 02:06 ..

[NicolasDorier]

we run clightning as root.

[NicolasDorier]

root@c41750064c74:/# ps aux
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root         1  0.0  0.0   2276    32 ?        Ss   02:06   0:00 /usr/bin/tini -g -- ./entrypoint.sh
root         6  0.7  2.7  62320 56888 ?        S    02:06   0:01 lightningd
root        12  0.0  0.1   6024  2108 ?        S    02:06   0:00 /usr/local/bin/../libexec/c-lightning/plugins/autoclean
root        13  0.0  0.1   6036  2416 ?        S    02:06   0:00 /usr/local/bin/../libexec/c-lightning/plugins/bcli
root        14  0.0  0.1   6116  2252 ?        S    02:06   0:00 /usr/local/bin/../libexec/c-lightning/plugins/fetchinvoice
root        15  0.0  0.1   6044  2256 ?        S    02:06   0:00 /usr/local/bin/../libexec/c-lightning/plugins/funder
root        16  0.0  0.1   6056  2160 ?        S    02:06   0:00 /usr/local/bin/../libexec/c-lightning/plugins/topology
root        17  0.0  0.1   6096  2156 ?        S    02:06   0:00 /usr/local/bin/../libexec/c-lightning/plugins/keysend
root        18  0.0  0.1   6100  2220 ?        S    02:06   0:00 /usr/local/bin/../libexec/c-lightning/plugins/offers
root        19  0.0  0.1   6152  2116 ?        S    02:06   0:00 /usr/local/bin/../libexec/c-lightning/plugins/pay
root        20  0.0  0.0   6036  1484 ?        S    02:06   0:00 /usr/local/bin/../libexec/c-lightning/plugins/txprepare
root        21  0.0  0.0   6068  1552 ?        S    02:06   0:00 /usr/local/bin/../libexec/c-lightning/plugins/spenderp
root        22  0.0  0.5 1007236 10532 ?       Sl   02:06   0:00 /root/.lightning/plugins/invoicewithdescriptionhash
root        34  0.0  0.1   6056  2128 ?        SL   02:06   0:00 /usr/local/libexec/c-lightning/lightning_hsmd
root        35  0.0  0.1   6320  2748 ?        S    02:06   0:00 /usr/local/libexec/c-lightning/lightning_connectd
root        36  0.0  0.0   6224  2040 ?        S    02:06   0:00 /usr/local/libexec/c-lightning/lightning_gossipd
root       160  0.1  0.1   3864  2956 pts/0    Ss   02:08   0:00 bash
root       749  0.0  0.1   7636  2700 pts/0    R+   02:08   0:00 ps aux

config

root@c41750064c74:/# cat /root/.lightning/config
bitcoin-datadir=/etc/bitcoin
bitcoin-rpcconnect=bitcoind
plugin-dir=/etc/clightningplugins

proxy=tor:9050

bind-addr=0.0.0.0:9735
network=bitcoin
announce-addr=btcpay.store.nicolas-dorier.com:9735
announce-addr=uewlcjmuuwcgs43lpcc7d64k2pf4xs7yyer7ztsq6cblyjxue3bc35qd.onion:9735
rpc-file=/root/.lightning/lightning-rpc

logs

root@btcpay763334:~/btcpayserver-docker# docker logs btcpayserver_clightning_bitcoin
network=bitcoin added in /root/.lightning/config
Waiting /root/.nbxplorer/btc_fully_synched to be created...
The chain is fully synched
Waiting /var/lib/tor/hidden_services/c-lightning/hostname to be created by tor...
announce-addr=uewlcjmuuwcgs43lpcc7d64k2pf4xs7yyer7ztsq6cblyjxue3bc35qd.onion:9735 added to /root/.lightning/config
rpc-file=/root/.lightning/lightning-rpc added to /root/.lightning/config
Installing bundled plugins
C-Lightning starting, listening on port 9735

When the bug is fixed, you can notice that we get logs from plugin

root@btcpay763334:~/btcpayserver-docker# docker logs btcpayserver_clightning_bitcoin
network=bitcoin added in /root/.lightning/config
Waiting /root/.nbxplorer/btc_fully_synched to be created...
root@btcpay763334:~/btcpayserver-docker# docker logs btcpayserver_clightning_bitcoin -f
network=bitcoin added in /root/.lightning/config
Waiting /root/.nbxplorer/btc_fully_synched to be created...
The chain is fully synched
Waiting /var/lib/tor/hidden_services/c-lightning/hostname to be created by tor...
announce-addr=uewlcjmuuwcgs43lpcc7d64k2pf4xs7yyer7ztsq6cblyjxue3bc35qd.onion:9735 added to /root/.lightning/config
rpc-file=/root/.lightning/lightning-rpc added to /root/.lightning/config
Installing bundled plugins
C-Lightning starting, listening on port 9735
2021-09-28T02:04:06.912Z INFO    plugin-bcli: bitcoin-cli initialized and connected to bitcoind.
plugin-invoicewithdescriptionhash  initialized plugin v1.2
2021-09-28T02:04:07.249Z INFO    lightningd: --------------------------------------------------
2021-09-28T02:04:07.249Z INFO    lightningd: Server started with public key 0286024f7f15211e3b037ca1d28cc70e60ebf0e39d6b79ba711e819ef1b239af52, alias YELLOWMONKEY (color #028602) and lightningd basedon-v0.10.1-2

Again: When I tried to debug the situation, I found out that code was blocked in the init of the first plugin loaded (bcli).
Logs I sent from the plugin didn't appear on lightningd. However, the init seemed to be correctly running. (I tried to create a dummy file from inside, and it worked)

[Kukks]

Actually, in the plugindir that we provide, we were not shipping any plugins. invoicewithdescriptionhash is actually in a different folder that CL looks for plugins (CL data directory/plugins)

[vincenzopalazzo]

Ok, I'm back with a small reproducible example, IMO there is no problem with the plugin but the problem is with the database creation at first startup, maybe with I/O operation in the container from C procedure?.

I have two different docker-compose configurations, with the same c-lightning image with just two plugins, inside where one got stuck and the other one no when it is the time to create the database.

So here I have a question, and maybe @cdecker has some experience with it: It is possible that we have some I/O operation stuck on the container? or maybe there is some permission related that our C procedure is stuck inside the container?

I can give also some copies and past examples to reproduce the problem, I ran them on the same AWS service in a Debian machine:

Docker container where I have the problem

https://github.com/clightning4j/clightning4j-node/blob/main/examples/ui-rest-mode-docker-compose.yml

Stuck with the actual status

admin@ip-172-31-17-191:~/clightning4j-node/examples$ sudo docker-compose -f ui-rest-mode-docker-compose.yml up
Starting examples_lnchecker_1 ... done
Starting examples_lightningd_1 ... done
Attaching to examples_lnchecker_1, examples_lightningd_1
lightningd_1  | /home/clightning4j
lnchecker_1   | 
lnchecker_1   | > ln-dashboard@0.1.0 start
lnchecker_1   | > next start
lnchecker_1   | 
lnchecker_1   | ready - started server on 0.0.0.0:3000, url: http://localhost:3000
lightningd_1  | Congratulations. This browser is configured to use Tor.
lightningd_1  | /entrypoint.sh: assuming arguments for lightningd
lightningd_1  | /entrypoint.sh: setting data directory to /home/clightning4j/.lightning
lightningd_1  | 2021-11-19T16:08:35.157Z INFO    plugin-manager: /usr/local/bin/../libexec/c-lightning/plugins/bcli: disabled via disable-plugin

Docker container where I have not the problem

https://github.com/clightning4j/clightning4j-node/blob/main/examples/rest-mode-docker-compose.yml

Completed with the actual status

admin@ip-172-31-17-191:~/clightning4j-node/examples$ sudo docker-compose -f rest-mode-docker-compose.yml up
WARNING: Found orphan containers (examples_lnchecker_1) for this project. If you removed or renamed this service in your compose file, you can run this command with the --remove-orphans flag to clean it up.
Recreating examples_lightningd_1 ... done
Attaching to examples_lightningd_1
lightningd_1  | /home/clightning4j
lightningd_1  | Congratulations. This browser is configured to use Tor.
lightningd_1  | /entrypoint.sh: assuming arguments for lightningd
lightningd_1  | /entrypoint.sh: setting data directory to /home/clightning4j/.lightning
lightningd_1  | 2021-11-19T15:59:28.493Z INFO    plugin-manager: /usr/local/bin/../libexec/c-lightning/plugins/bcli: disabled via disable-plugin
lightningd_1  | 2021-11-19T15:59:28.493Z INFO    lightningd: Creating configuration directory /home/clightning4j/.lightning/testnet
lightningd_1  | 2021-11-19T15:59:28.493Z INFO    plugin-manager: /usr/local/bin/../libexec/c-lightning/plugins/bcli: disabled via disable-plugin
lightningd_1  | 2021-11-19T15:59:35.945Z INFO    database: Creating database
lightningd_1  | 2021-11-19T15:59:36.086Z UNUSUAL hsmd: HSM: created new hsm_secret file
lightningd_1  | 2021-11-19T15:59:36.293Z INFO    connectd: Static Tor service onion address: "h7onvakwb3rfecelfrczt7e3adxqsjeupqazek64desfn25confixgyd.onion:9735,127.0.0.1:9735" bound from extern port 9735 
lightningd_1  | 2021-11-19T15:59:36.509Z INFO    plugin-btcli4j.sh: btcli4j: proxy enable at 127.0.0.1:9050
lightningd_1  | 2021-11-19T15:59:36.517Z INFO    plugin-btcli4j.sh: btcli4j: proxy type is ipv4
lightningd_1  | 2021-11-19T15:59:36.527Z INFO    plugin-btcli4j.sh: btcli4j: tor version is 3
lightningd_1  | 2021-11-19T15:59:44.457Z INFO    lightningd: --------------------------------------------------
lightningd_1  | 2021-11-19T15:59:44.457Z INFO    lightningd: Server started with public key 02b1a41a224fb974152cd504820aebf526762739bca8f7d21b093b4c95b29be5a3, alias clightning-node (color #02b1a4) and lightningd v0.10.2-37-gd8c59fc-modded
lightningd_1  | 2021-11-19T15:59:44.583Z INFO    plugin-lightning-rest.sh: Auto init jrest init function calla after a delay of 2000 millisecond
lightningd_1  | 2021-11-19T15:59:51.353Z INFO    plugin-lightning-rest.sh: jrest: init completed