plugin-spenderp dies during integration test

[ksedgwic]

trafficstars

Issue and Steps to Reproduce

Running CLN v24.02rc2 + vls integration test mods: https://github.com/lightning-signer/c-lightning/pull/106

Full logs: 2024-02-spenderp-dies.tar.gz

Two tests failed with this problem:

• tests/test_connection.py::test_opening_tiny_channel[True]
• tests/test_connection.py::test_wumbo_channels
• There is a third failing test in the run which failed for other reasons

This run had EXPERIMENTAL_DUAL_FUND=1

Grepping for spenderp in lightning.log for the wumbo test yields:

... lots omitted ...
lightningd-1 2024-02-23T01:47:41.278Z DEBUG   plugin-spenderp: mfc 34: fundpsbt.
lightningd-1 2024-02-23T01:47:41.287Z DEBUG   plugin-spenderp: mfc 34: fundpsbt done.
lightningd-1 2024-02-23T01:47:41.287Z INFO    plugin-spenderp: 'all' was too large for non-wumbo channel, trimming from 50296748sat to 16777215sat
lightningd-1 2024-02-23T01:47:41.289Z DEBUG   plugin-spenderp: mfc 34: fundpsbt.
lightningd-1 2024-02-23T01:47:41.301Z DEBUG   plugin-spenderp: mfc 34: fundpsbt done.
lightningd-1 2024-02-23T01:47:41.301Z DEBUG   plugin-spenderp: mfc 34: fundchannel_start parallel with PSBT cHNidP8BAgQCAAAAAQMEbAAAAAEEAQEBBQEBAQYBAwH7BAIAAAAAAQD2AgAAAAABAaYVgi6/BcPnwIwhETPl4ef7mBY7DDS5MrSODT+YKDkQAAAAAAD9////AgAAAAEAAAAAIgAgW4zTuRTPZ83Y+mJzyTA1PdNkdnNPvZYhAsLfU7kIgM2q7P8CAAAAACJRIGP/7k6n1R5srfkIbihqJSeSKqoluMU66/MvoyoKYn9aAkcwRAIgWz84HxN4j7h8cqJ168uW+w5uJ2Rb3kru0hyCLs7bcwYCICQ7xYdVaZV4vYxWILpRHfEJj0qOSkKlAooEosDPVWgWASED10VEXJNiZl8i4NlunnZvJz8yYN6jnIp2v6Bd0mhN3M9mAAAAAQErquz/AgAAAAAiUSBj/+5Op9UebK35CG4oaiUnkiqqJbjFOuvzL6MqCmJ/WgEOIETNtAT6FJNS9srYxOhFl9NQg4nFaLF9qO/cIl/BWy0DAQ8EAQAAAAEQBP3///8M/AlsaWdodG5pbmcCAgABDPwJbGlnaHRuaW5nAQjVfUd+LN3SFgABAwhV2f8BAAAAAAEEIlEgAHTXf13QPvlcSEsMoAWtGC8UiGnr680CXDzF3PDA96oM/AlsaWdodG5pbmcBCKwA/pWJtHzQAA==
lightningd-1 2024-02-23T01:47:41.301Z DEBUG   plugin-spenderp: mfc 34, dest 0: openchannel_init 035d2b1192dfba134e10e540875d366ebc8bc353d5aa766b80c090b39c3a5d885d.
lightningd-1 2024-02-23T01:47:41.406Z DEBUG   plugin-spenderp: mfc 34, dest 0: openchannel_init 035d2b1192dfba134e10e540875d366ebc8bc353d5aa766b80c090b39c3a5d885d done.
lightningd-1 2024-02-23T01:47:41.406Z DEBUG   plugin-spenderp: mfc 34: parallel channel starts done.
lightningd-1 2024-02-23T01:47:41.406Z DEBUG   plugin-spenderp: mfc 34: Creating funding tx.
lightningd-1 2024-02-23T01:47:41.406Z DEBUG   plugin-spenderp: mfc 34: parallel `openchannel_update`.
lightningd-1 2024-02-23T01:47:41.406Z DEBUG   plugin-spenderp: mfc 34, dest 0: `openchannel_update` 035d2b1192dfba134e10e540875d366ebc8bc353d5aa766b80c090b39c3a5d885d with psbt cHNidP8BAgQCAAAAAQMEbAAAAAEEAQEBBQECAQYBAwH7BAIAAAAAAQD2AgAAAAABAaYVgi6/BcPnwIwhETPl4ef7mBY7DDS5MrSODT+YKDkQAAAAAAD9////AgAAAAEAAAAAIgAgW4zTuRTPZ83Y+mJzyTA1PdNkdnNPvZYhAsLfU7kIgM2q7P8CAAAAACJRIGP/7k6n1R5srfkIbihqJSeSKqoluMU66/MvoyoKYn9aAkcwRAIgWz84HxN4j7h8cqJ168uW+w5uJ2Rb3kru0hyCLs7bcwYCICQ7xYdVaZV4vYxWILpRHfEJj0qOSkKlAooEosDPVWgWASED10VEXJNiZl8i4NlunnZvJz8yYN6jnIp2v6Bd0mhN3M9mAAAAAQErquz/AgAAAAAiUSBj/+5Op9UebK35CG4oaiUnkiqqJbjFOuvzL6MqCmJ/WgEOIETNtAT6FJNS9srYxOhFl9NQg4nFaLF9qO/cIl/BWy0DAQ8EAQAAAAEQBP3///8M/AlsaWdodG5pbmcCAgABDPwJbGlnaHRuaW5nAQjVfUd+LN3SFgABAwj///8AAAAAAAEEIgAgtVNGSdg4ZL9mp8QE/zDuB0owLgCViZaGvrXY2uDj2HAM/AlsaWdodG5pbmcBCIwD/Ali6oTQAAEDCFXZ/wEAAAAAAQQiUSAAdNd/XdA++VxISwygBa0YLxSIaevrzQJcPMXc8MD3qgz8CWxpZ2h0bmluZwEIrAD+lYm0fNAA
lightningd-1 2024-02-23T01:47:41.795Z INFO    plugin-spenderp: Killing plugin: exited during normal operation
lightningd-1 2024-02-23T01:47:41.795Z **BROKEN** plugin-spenderp: Plugin marked as important, shutting down lightningd!

It sure looks like the the plugin was happy and then broke suddenly at the end?

NOTES:

• the VLS modifications to the v24.02rc2 release are mostly integration test harness to test w/ VLS
• seems to mostly happen w/ dual-funding enabled

[cdecker]

Could you instrument the node with logging on JSON-RPC calls? spenderp is the channel funding plugin, which uses the psbt-based RPC methods to actually get things signed. I suspect that since the log writing the PSBT it wants to get signed or modified, that there is an error in how we handle that.