Testing v0.12.0rc2, some bookkeeper related tests fail

[SimonVrouwe]

Issue and Steps to Reproduce

git checkout v0.12.0rc2
make clean && ./configure --enable-developer --enable-experimental-features --disable-rust && make

Some tests fail:

FAILED tests/test_bookkeeper.py::test_bookkeeping_closing_trimmed_htlcs - assert 0 == 1
FAILED tests/test_bookkeeper.py::test_bookkeeping_closing_subsat_htlcs - assert 0 == 1
FAILED tests/test_closing.py::test_penalty_htlc_tx_timeout - assert False
FAILED tests/test_closing.py::test_penalty_rbf_burn - assert 0 == 1
FAILED tests/test_closing.py::test_onchain_their_unilateral_out - AssertionError
FAILED tests/test_opening.py::test_zeroconf_public - AssertionError

Bitcoin Core version v23.0.0

With a normal build at least test_bookkeeping_closing_subsat_htlcs fails, see below for partial log.
What I found so far is that bkpr plugin seems to miss close_fee:

>       assert len(close_fee) == 1
E       assert 0 == 1
E        +  where 0 = len([])

tests/test_bookkeeper.py:99: AssertionError

(cldev) simon@gamepc:~/git/SimonVrouwe/lightning$ pytest tests/ -s -k 'test_bookkeeping_closing_subsat_htlcs'
============================================================================================================================= test session starts =============================================================================================================================
platform linux -- Python 3.7.3, pytest-7.1.2, pluggy-1.0.0
benchmark: 3.2.2 (defaults: timer=time.perf_counter disable_gc=False min_rounds=5 min_time=0.000005 max_time=1.0 calibration_precision=10 warmup=False warmup_iterations=100000)
rootdir: /home/simon/git/SimonVrouwe/lightning
plugins: xdist-2.5.0, timeout-2.1.0, benchmark-3.2.2, flaky-3.7.0, test-groups-1.0.3, forked-1.4.0, custom-exit-code-0.3.0, rerunfailures-9.1.1
collected 526 items / 525 deselected / 1 selected                                                                                                                                                                                                                             

tests/test_bookkeeper.py Running tests in /tmp/ltests-gecvmt23
Throttler delayed startup for 0.0010685920715332031 seconds
Throttler delayed startup for 0.1016073226928711 seconds
-- snip --
lightningd-2 2022-08-11T16:11:39.623Z DEBUG   gossipd: Deleting channel 103x1x1 due to the funding outpoint being spent
lightningd-2 2022-08-11T16:11:39.630Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: delayed_to_us_feerate = 7500, htlc_feerate = 11000, penalty_feerate = 7500
lightningd-2 2022-08-11T16:11:39.630Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: Tracking output ebe71e3c0de2d778c67355c326cecada813f9f61b58484c70f147482ff144c01:1: FUNDING_TRANSACTION/FUNDING_OUTPUT
lightningd-2 2022-08-11T16:11:39.631Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: Remote per-commit point: 02f7dd41f74444740d99538d3c95b3c478b1bdbf6a9066139a4179668119250dde
lightningd-2 2022-08-11T16:11:39.631Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: Old remote per-commit point: 03fe980a9a93fe5aa1b61215455a965bb6e291b10671a0b2df0d267e5015e07907
lightningd-2 2022-08-11T16:11:39.631Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: reducing max_possible_feerate from 11000...
lightningd-2 2022-08-11T16:11:39.631Z DEBUG   plugin-bcli: sendrawtx exit 25 (bitcoin-cli -regtest -datadir=/tmp/ltests-gecvmt23/test_bookkeeping_closing_subsat_htlcs_1/lightning-2/ -rpcport=53229 -rpcuser=... -rpcpassword=... sendrawtransaction 02000000000101014c14ff8274140fc78484b5619f3f81dacace26c35573c678d7e20d3c1ee7eb01000000009db0e28002a00f00000000000022002039b989a62357b0ac389ed364aec6c165e5aaebf5b4e3c1bd9e0c06b9259eeb5a83130f0000000000160014e89954fac8f7a2dce51e095d7beb5271c3f7da56040047304402202d4187615e7160a34b6564dc504bbfe3432ba2e77d46ed9459eff59482dd8ddc0220558ed6ce6003a4cb830712038f721bfd38f0729541a58e6926b30be56faef3e50147304402205d7a2a7a3bfcc5cac09c5c3c4f952a8831f95c3bb6ecca10de8c14a7260682b5022028fb6c321279a9558cf5de16c9613bdd9ab34f9db3b33c5a57a3ec3dc637e1d50147522102324266de8403b3ab157a09f1f784d587af61831c998c151bcc21bb74c2b2314b2102e3bd38009866c9da8ec4aa99cc4ea9c6c0dd46df15c61ef0ce1f271291714e5752ae9c3ed620) error code: -25\nerror message:\nbad-txns-inputs-missingorspent
lightningd-2 2022-08-11T16:11:39.631Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: ... to 11000
lightningd-2 2022-08-11T16:11:39.631Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: commitnum = 6, revocations_received = 6
lightningd-2 2022-08-11T16:11:39.631Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: Their unilateral tx, old commit point
lightningd-2 2022-08-11T16:11:39.632Z INFO    0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: State changed from FUNDING_SPEND_SEEN to ONCHAIN
lightningd-2 2022-08-11T16:11:39.639Z DEBUG   lightningd: Adding block 105: 4d7255c1d3ddcabd53543aa4893010d2989e6b2e1e1274e5c5d293de10cf387f
lightningd-2 2022-08-11T16:11:39.644Z DEBUG   plugin-bookkeeper: coin_move 2 (channel_close) 0msat -4000333msat chain_mvt 1660234299
lightningd-2 2022-08-11T16:11:39.644Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: billboard perm: Tracking their unilateral close
lightningd-2 2022-08-11T16:11:39.650Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: Resolved FUNDING_TRANSACTION/FUNDING_OUTPUT by THEIR_UNILATERAL (67107d17c0953fd6b08b5e72ff46af1b696102c575740a2296d22eae6a093ca5)
lightningd-2 2022-08-11T16:11:39.650Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: Deriving keyset 6: per_commit_point=03fe980a9a93fe5aa1b61215455a965bb6e291b10671a0b2df0d267e5015e07907 self_payment_basepoint=022dbc0053dd6f3310d84e55eebaacfad53fe3e3ec3c2cecb1cffebdd95fa8063f other_payment_basepoint=02abc10666592840eb562f2afaedfac56930b4482ec5d8b61b5a4485b383c2cba8 self_htlc_basepoint=02346928c7642a1098a328e2787254c060f03a6b2c06af78a128868f913945d447 other_htlc_basepoint=03e0a7bb422b254f54bc954be05bd6823a7b7a4b996ff8d3079ca211590fb5df39 self_delayed_basepoint=03b5aa92c890a616a425948f6eef8be810e7b65d1a6fe5bf5df62d83e1727f81d6 other_revocation_basepoint=03cdcb22e07f0f83805ae79d0fa1b777dc1dbd27c1dd2840469d72cf305332d663
lightningd-2 2022-08-11T16:11:39.656Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: Deconstructing unilateral tx: 6 using keyset:  self_revocation_key: 025f3016168568a796c8271ea0a4517e201e84594f67684cbbbebc5e214cda3a5e self_delayed_payment_key: 03942b71443a5fe81ab9713165763ee91968759c20ad5b0cd9a210e72474070e26 self_payment_key: 03d9e34c5c06ab41fc1ff6256e62a2b483166e7170d25ba423ca76fb60f77096a1 other_payment_key: 02abc10666592840eb562f2afaedfac56930b4482ec5d8b61b5a4485b383c2cba8 self_htlc_key: 0394c0631f627610f5bd9233672d4125d5abd8c814db0430b5d07ece5945363085 other_htlc_key: 02224f8d4dd6878b0f84b913e8637d0130d88485e20f5bb060aa0b0b88c8741151
lightningd-2 2022-08-11T16:11:39.656Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: Output 0: 001445503fa4b65ade3ffdb1a92057688456c9ffae13
lightningd-2 2022-08-11T16:11:39.656Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: Output 1: 0020be82765fdb17fd5568f2dd31c6cf1aabc620ef338995ec5d9a2f3e42f43ae487
lightningd-2 2022-08-11T16:11:39.656Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: Script to-them: 5: 0020be82765fdb17fd5568f2dd31c6cf1aabc620ef338995ec5d9a2f3e42f43ae487 (6321025f3016168568a796c8271ea0a4517e201e84594f67684cbbbebc5e214cda3a5e6755b2752103942b71443a5fe81ab9713165763ee91968759c20ad5b0cd9a210e72474070e2668ac)
lightningd-2 2022-08-11T16:11:39.656Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: Script to-me: 001445503fa4b65ade3ffdb1a92057688456c9ffae13
lightningd-2 2022-08-11T16:11:39.657Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: Tracking output 67107d17c0953fd6b08b5e72ff46af1b696102c575740a2296d22eae6a093ca5:0: THEIR_UNILATERAL/OUTPUT_TO_US
lightningd-2 2022-08-11T16:11:39.657Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: Ignoring output 67107d17c0953fd6b08b5e72ff46af1b696102c575740a2296d22eae6a093ca5:0: THEIR_UNILATERAL/OUTPUT_TO_US
lightningd-2 2022-08-11T16:11:39.657Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: adding utxo to watch 67107d17c0953fd6b08b5e72ff46af1b696102c575740a2296d22eae6a093ca5:0, csv 1
lightningd-2 2022-08-11T16:11:39.661Z DEBUG   lightningd: Adding block 106: 7154aee46c83587694d9a29f42dc45c645eaaed6356fecc68970e7873a68e808
lightningd-2 2022-08-11T16:11:39.666Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: Tracking output 67107d17c0953fd6b08b5e72ff46af1b696102c575740a2296d22eae6a093ca5:1: THEIR_UNILATERAL/DELAYED_OUTPUT_TO_THEM
lightningd-2 2022-08-11T16:11:39.666Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: Ignoring output 67107d17c0953fd6b08b5e72ff46af1b696102c575740a2296d22eae6a093ca5:1: THEIR_UNILATERAL/DELAYED_OUTPUT_TO_THEM
lightningd-2 2022-08-11T16:11:39.666Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: billboard: All outputs resolved: waiting 100 more blocks before forgetting channel
lightningd-2 2022-08-11T16:11:39.677Z DEBUG   plugin-bookkeeper: coin_move 2 (deposit) 4000000msat -0msat chain_mvt 1660234299
lightningd-2 2022-08-11T16:11:39.677Z DEBUG   plugin-bookkeeper: coin_move 2 (to_them) 988035000msat -0msat chain_mvt 1660234299
lightningd-2 2022-08-11T16:11:39.681Z DEBUG   lightningd: Adding block 107: 56da75fca1bfc7f9a3ae0ed726ca9c804de21ea4b52861fa24e40ece8ffdfa7a
lightningd-2 2022-08-11T16:11:39.698Z DEBUG   lightningd: Adding block 108: 3713fed617be154f6f10ccd8a35d97378da0201539c60f737cc5a81da53f2fa4
lightningd-2 2022-08-11T16:11:39.711Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: Got depth change 0->5 for 67107d17c0953fd6b08b5e72ff46af1b696102c575740a2296d22eae6a093ca5
lightningd-2 2022-08-11T16:11:39.711Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: Got depth change 0->6 for ebe71e3c0de2d778c67355c326cecada813f9f61b58484c70f147482ff144c01
lightningd-2 2022-08-11T16:11:39.711Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: Funding tx ebe71e3c0de2d778c67355c326cecada813f9f61b58484c70f147482ff144c01 depth 6 of 1
lightningd-2 2022-08-11T16:11:39.712Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: Funding tx ebe71e3c0de2d778c67355c326cecada813f9f61b58484c70f147482ff144c01 confirmed, but peer in state ONCHAIN
lightningd-2 2022-08-11T16:11:39.712Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: attempting update blockheight 014c14ff8274140fc78484b5619f3f81dacace26c35573c678d7e20d3c1ee7ea
lightningd-2 2022-08-11T16:11:39.712Z DEBUG   lightningd: sendrawtransaction: 02000000000101014c14ff8274140fc78484b5619f3f81dacace26c35573c678d7e20d3c1ee7eb01000000009db0e28002a00f00000000000022002039b989a62357b0ac389ed364aec6c165e5aaebf5b4e3c1bd9e0c06b9259eeb5a83130f0000000000160014e89954fac8f7a2dce51e095d7beb5271c3f7da56040047304402202d4187615e7160a34b6564dc504bbfe3432ba2e77d46ed9459eff59482dd8ddc0220558ed6ce6003a4cb830712038f721bfd38f0729541a58e6926b30be56faef3e50147304402205d7a2a7a3bfcc5cac09c5c3c4f952a8831f95c3bb6ecca10de8c14a7260682b5022028fb6c321279a9558cf5de16c9613bdd9ab34f9db3b33c5a57a3ec3dc637e1d50147522102324266de8403b3ab157a09f1f784d587af61831c998c151bcc21bb74c2b2314b2102e3bd38009866c9da8ec4aa99cc4ea9c6c0dd46df15c61ef0ce1f271291714e5752ae9c3ed620
lightningd-2 2022-08-11T16:11:39.716Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_NEW_BLOCKHEIGHT_REPLY with 0 fds
lightningd-2 2022-08-11T16:11:39.716Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: Got new message WIRE_ONCHAIND_DEPTH
lightningd-2 2022-08-11T16:11:39.716Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: Sending 0 missing htlc messages
lightningd-2 2022-08-11T16:11:39.716Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: FUNDING_TRANSACTION/FUNDING_OUTPUT->THEIR_UNILATERAL depth 5
lightningd-2 2022-08-11T16:11:39.716Z DEBUG   plugin-bookkeeper: account wallet has balance 4000000msat
lightningd-2 2022-08-11T16:11:39.716Z DEBUG   plugin-bookkeeper: Snapshot balances updated
lightningd-2 2022-08-11T16:11:39.716Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: THEIR_UNILATERAL/OUTPUT_TO_US->SELF depth 5
lightningd-2 2022-08-11T16:11:39.717Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: THEIR_UNILATERAL/DELAYED_OUTPUT_TO_THEM->SELF depth 5
lightningd-2 2022-08-11T16:11:39.717Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: billboard: All outputs resolved: waiting 95 more blocks before forgetting channel
lightningd-2 2022-08-11T16:11:39.723Z DEBUG   plugin-bcli: sendrawtx exit 25 (bitcoin-cli -regtest -datadir=/tmp/ltests-gecvmt23/test_bookkeeping_closing_subsat_htlcs_1/lightning-2/ -rpcport=53229 -rpcuser=... -rpcpassword=... sendrawtransaction 02000000000101014c14ff8274140fc78484b5619f3f81dacace26c35573c678d7e20d3c1ee7eb01000000009db0e28002a00f00000000000022002039b989a62357b0ac389ed364aec6c165e5aaebf5b4e3c1bd9e0c06b9259eeb5a83130f0000000000160014e89954fac8f7a2dce51e095d7beb5271c3f7da56040047304402202d4187615e7160a34b6564dc504bbfe3432ba2e77d46ed9459eff59482dd8ddc0220558ed6ce6003a4cb830712038f721bfd38f0729541a58e6926b30be56faef3e50147304402205d7a2a7a3bfcc5cac09c5c3c4f952a8831f95c3bb6ecca10de8c14a7260682b5022028fb6c321279a9558cf5de16c9613bdd9ab34f9db3b33c5a57a3ec3dc637e1d50147522102324266de8403b3ab157a09f1f784d587af61831c998c151bcc21bb74c2b2314b2102e3bd38009866c9da8ec4aa99cc4ea9c6c0dd46df15c61ef0ce1f271291714e5752ae9c3ed620) error code: -25\nerror message:\nbad-txns-inputs-missingorspent
lightningd-2 2022-08-11T16:11:39.723Z DEBUG   lightningd: Expected error broadcasting tx 02000000000101014c14ff8274140fc78484b5619f3f81dacace26c35573c678d7e20d3c1ee7eb01000000009db0e28002a00f00000000000022002039b989a62357b0ac389ed364aec6c165e5aaebf5b4e3c1bd9e0c06b9259eeb5a83130f0000000000160014e89954fac8f7a2dce51e095d7beb5271c3f7da56040047304402202d4187615e7160a34b6564dc504bbfe3432ba2e77d46ed9459eff59482dd8ddc0220558ed6ce6003a4cb830712038f721bfd38f0729541a58e6926b30be56faef3e50147304402205d7a2a7a3bfcc5cac09c5c3c4f952a8831f95c3bb6ecca10de8c14a7260682b5022028fb6c321279a9558cf5de16c9613bdd9ab34f9db3b33c5a57a3ec3dc637e1d50147522102324266de8403b3ab157a09f1f784d587af61831c998c151bcc21bb74c2b2314b2102e3bd38009866c9da8ec4aa99cc4ea9c6c0dd46df15c61ef0ce1f271291714e5752ae9c3ed620: error code: -25\nerror message:\nbad-txns-inputs-missingorspent
lightningd-1 2022-08-11T16:11:40.245Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_GET_ADDRS_REPLY with 0 fds
lightningd-1 2022-08-11T16:11:40.246Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-connectd: Connected out, starting crypto
lightningd-2 2022-08-11T16:11:40.246Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-hsmd: Got WIRE_HSMD_ECDH_REQ
lightningd-2 2022-08-11T16:11:40.247Z DEBUG   hsmd: Client: Received message 1 from client
lightningd-1 2022-08-11T16:11:40.248Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-hsmd: Got WIRE_HSMD_ECDH_REQ
lightningd-1 2022-08-11T16:11:40.248Z DEBUG   hsmd: Client: Received message 1 from client
lightningd-1 2022-08-11T16:11:40.248Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-connectd: Connect OUT
lightningd-1 2022-08-11T16:11:40.248Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-connectd: peer_out WIRE_INIT
lightningd-2 2022-08-11T16:11:40.248Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-connectd: Connect IN
lightningd-1 2022-08-11T16:11:40.248Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-connectd: peer_in WIRE_INIT
lightningd-1 2022-08-11T16:11:40.249Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-connectd: Handed peer, entering loop
lightningd-1 2022-08-11T16:11:40.249Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-gossipd: seeker: chosen as startup peer
lightningd-1 2022-08-11T16:11:40.249Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-connectd: peer_out WIRE_GOSSIP_TIMESTAMP_FILTER
lightningd-1 2022-08-11T16:11:40.249Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-gossipd: seeker: starting gossip
lightningd-2 2022-08-11T16:11:40.249Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-connectd: peer_out WIRE_INIT
lightningd-2 2022-08-11T16:11:40.249Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-connectd: peer_in WIRE_INIT
lightningd-2 2022-08-11T16:11:40.249Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-gossipd: seeker: chosen as startup peer
lightningd-1 2022-08-11T16:11:40.249Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-connectd: peer_in WIRE_GOSSIP_TIMESTAMP_FILTER
lightningd-2 2022-08-11T16:11:40.249Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-gossipd: seeker: starting gossip
lightningd-2 2022-08-11T16:11:40.249Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-connectd: Handed peer, entering loop
lightningd-2 2022-08-11T16:11:40.250Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-connectd: peer_out WIRE_GOSSIP_TIMESTAMP_FILTER
lightningd-2 2022-08-11T16:11:40.250Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-connectd: peer_in WIRE_GOSSIP_TIMESTAMP_FILTER
lightningd-2 2022-08-11T16:11:41.172Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_GET_ADDRS_REPLY with 0 fds
lightningd-1 2022-08-11T16:11:53.483Z DEBUG   lightningd: Adding block 104: 53733a47f4fc460d6bd189af90c14d6621e0c8decde33dd093adf0c56b18f38c
lightningd-1 2022-08-11T16:11:53.484Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-chan#1: Got UTXO spend for ebe71e3c0de2d778c67355c326cecada813f9f61b58484c70f147482ff144c01:1: 67107d17c0953fd6b08b5e72ff46af1b696102c575740a2296d22eae6a093ca5
lightningd-1 2022-08-11T16:11:53.484Z UNUSUAL 022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-chan#1: Peer permanent failure in AWAITING_UNILATERAL: Funding transaction spent
lightningd-1 2022-08-11T16:11:53.485Z DEBUG   lightningd: Broadcasting txid 67107d17c0953fd6b08b5e72ff46af1b696102c575740a2296d22eae6a093ca5
lightningd-1 2022-08-11T16:11:53.485Z DEBUG   lightningd: sendrawtransaction: 02000000000101014c14ff8274140fc78484b5619f3f81dacace26c35573c678d7e20d3c1ee7eb01000000009db0e28002a00f00000000000016001445503fa4b65ade3ffdb1a92057688456c9ffae1383130f0000000000220020be82765fdb17fd5568f2dd31c6cf1aabc620ef338995ec5d9a2f3e42f43ae487040047304402201e1f7a62d64bbe40b4fd52b6eeab188a414a43748fd7282e3c7d9389094025f3022020043f97d079fddbac2f35468457974c5e4c82347ed3bfcf5766d222a6b75fc70147304402203aacce18fe2cbdea553fcbda9ffd5e26b7573e371219c1eef98d1ab9bea3027f022031bde3ec060d007e180d499a85563f04195f8c39bbb72b4195416e1acbab684a0147522102324266de8403b3ab157a09f1f784d587af61831c998c151bcc21bb74c2b2314b2102e3bd38009866c9da8ec4aa99cc4ea9c6c0dd46df15c61ef0ce1f271291714e5752ae9c3ed620
lightningd-1 2022-08-11T16:11:53.485Z INFO    022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-chan#1: State changed from AWAITING_UNILATERAL to FUNDING_SPEND_SEEN
lightningd-1 2022-08-11T16:11:53.488Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: pid 4560, msgfd 59
lightningd-1 2022-08-11T16:11:53.489Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-chan#1: channel->static_remotekey_start[LOCAL] 0
lightningd-1 2022-08-11T16:11:53.495Z DEBUG   hsmd: Client: Received message 5 from client
lightningd-1 2022-08-11T16:11:53.496Z DEBUG   hsmd: new_client: 1
lightningd-1 2022-08-11T16:11:53.496Z DEBUG   gossipd: Deleting channel 103x1x1 due to the funding outpoint being spent
lightningd-1 2022-08-11T16:11:53.498Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: delayed_to_us_feerate = 7500, htlc_feerate = 11000, penalty_feerate = 7500
lightningd-1 2022-08-11T16:11:53.498Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Tracking output ebe71e3c0de2d778c67355c326cecada813f9f61b58484c70f147482ff144c01:1: FUNDING_TRANSACTION/FUNDING_OUTPUT
lightningd-1 2022-08-11T16:11:53.499Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Remote per-commit point: 024bb699a1ac413d11362a9dab8eaa6d61a2c0e3fab2d0fdfbbcac68bfffeb607e
lightningd-1 2022-08-11T16:11:53.499Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Old remote per-commit point: 03da26778a010fd68b912a615a8cbbc45a0dcd950503489e63f6d64b6754c9e10a
lightningd-1 2022-08-11T16:11:53.499Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: reducing max_possible_feerate from 11000...
lightningd-1 2022-08-11T16:11:53.499Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: ... to 11000
lightningd-1 2022-08-11T16:11:53.499Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: commitnum = 6, revocations_received = 6
lightningd-1 2022-08-11T16:11:53.499Z INFO    022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-chan#1: State changed from FUNDING_SPEND_SEEN to ONCHAIN
lightningd-1 2022-08-11T16:11:53.507Z DEBUG   plugin-bcli: sendrawtx exit 27 (bitcoin-cli -regtest -datadir=/tmp/ltests-gecvmt23/test_bookkeeping_closing_subsat_htlcs_1/lightning-1/ -rpcport=37455 -rpcuser=... -rpcpassword=... sendrawtransaction 02000000000101014c14ff8274140fc78484b5619f3f81dacace26c35573c678d7e20d3c1ee7eb01000000009db0e28002a00f00000000000016001445503fa4b65ade3ffdb1a92057688456c9ffae1383130f0000000000220020be82765fdb17fd5568f2dd31c6cf1aabc620ef338995ec5d9a2f3e42f43ae487040047304402201e1f7a62d64bbe40b4fd52b6eeab188a414a43748fd7282e3c7d9389094025f3022020043f97d079fddbac2f35468457974c5e4c82347ed3bfcf5766d222a6b75fc70147304402203aacce18fe2cbdea553fcbda9ffd5e26b7573e371219c1eef98d1ab9bea3027f022031bde3ec060d007e180d499a85563f04195f8c39bbb72b4195416e1acbab684a0147522102324266de8403b3ab157a09f1f784d587af61831c998c151bcc21bb74c2b2314b2102e3bd38009866c9da8ec4aa99cc4ea9c6c0dd46df15c61ef0ce1f271291714e5752ae9c3ed620) error code: -27\nerror message:\nTransaction already in block chain
lightningd-1 2022-08-11T16:11:53.507Z DEBUG   plugin-bookkeeper: coin_move 2 (channel_close) 0msat -995999667msat chain_mvt 1660234313
lightningd-1 2022-08-11T16:11:53.507Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: billboard perm: Tracking our own unilateral close
lightningd-1 2022-08-11T16:11:53.511Z DEBUG   lightningd: Adding block 105: 4d7255c1d3ddcabd53543aa4893010d2989e6b2e1e1274e5c5d293de10cf387f
lightningd-1 2022-08-11T16:11:53.515Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT
lightningd-1 2022-08-11T16:11:53.515Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Resolved FUNDING_TRANSACTION/FUNDING_OUTPUT by OUR_UNILATERAL (67107d17c0953fd6b08b5e72ff46af1b696102c575740a2296d22eae6a093ca5)
lightningd-1 2022-08-11T16:11:53.515Z DEBUG   hsmd: Client: Received message 18 from client
lightningd-1 2022-08-11T16:11:53.515Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Deconstructing unilateral tx: 6 using keyset:  self_revocation_key: 025f3016168568a796c8271ea0a4517e201e84594f67684cbbbebc5e214cda3a5e self_delayed_payment_key: 03942b71443a5fe81ab9713165763ee91968759c20ad5b0cd9a210e72474070e26 self_payment_key: 03d9e34c5c06ab41fc1ff6256e62a2b483166e7170d25ba423ca76fb60f77096a1 other_payment_key: 02abc10666592840eb562f2afaedfac56930b4482ec5d8b61b5a4485b383c2cba8 self_htlc_key: 0394c0631f627610f5bd9233672d4125d5abd8c814db0430b5d07ece5945363085 other_htlc_key: 02224f8d4dd6878b0f84b913e8637d0130d88485e20f5bb060aa0b0b88c8741151
lightningd-1 2022-08-11T16:11:53.516Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-hsmd: Got WIRE_HSMD_SIGN_DELAYED_PAYMENT_TO_US
lightningd-1 2022-08-11T16:11:53.516Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Script to-me: 5: 0020be82765fdb17fd5568f2dd31c6cf1aabc620ef338995ec5d9a2f3e42f43ae487 (6321025f3016168568a796c8271ea0a4517e201e84594f67684cbbbebc5e214cda3a5e6755b2752103942b71443a5fe81ab9713165763ee91968759c20ad5b0cd9a210e72474070e2668ac)
lightningd-1 2022-08-11T16:11:53.516Z DEBUG   hsmd: Client: Received message 12 from client
lightningd-1 2022-08-11T16:11:53.516Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Script to-them: 001445503fa4b65ade3ffdb1a92057688456c9ffae13
lightningd-1 2022-08-11T16:11:53.516Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Output 0: 001445503fa4b65ade3ffdb1a92057688456c9ffae13
lightningd-1 2022-08-11T16:11:53.516Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Output 1: 0020be82765fdb17fd5568f2dd31c6cf1aabc620ef338995ec5d9a2f3e42f43ae487
lightningd-1 2022-08-11T16:11:53.516Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Tracking output 67107d17c0953fd6b08b5e72ff46af1b696102c575740a2296d22eae6a093ca5:0: OUR_UNILATERAL/OUTPUT_TO_THEM
lightningd-1 2022-08-11T16:11:53.516Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Ignoring output 67107d17c0953fd6b08b5e72ff46af1b696102c575740a2296d22eae6a093ca5:0: OUR_UNILATERAL/OUTPUT_TO_THEM
lightningd-1 2022-08-11T16:11:53.516Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Tracking output 67107d17c0953fd6b08b5e72ff46af1b696102c575740a2296d22eae6a093ca5:1: OUR_UNILATERAL/DELAYED_OUTPUT_TO_US
lightningd-1 2022-08-11T16:11:53.516Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Propose handling OUR_UNILATERAL/DELAYED_OUTPUT_TO_US by OUR_DELAYED_RETURN_TO_WALLET (02000000000101a53c096aae2ed296220a7475c50261691baf46ff725e8bb0d63f95c0177d10670100000000050000000164050f0000000000160014071c49cad2f420f3c805f9f6b98a57269cb14150034730440220465647fd5b0ede0d04a662b9d2b9352d813f3977db7b62ca84150fabd4b442e60220732d713f354c0f0d81ea4d2a6c4e9960ccf97e70c1348b624eca6e381869718701004b6321025f3016168568a796c8271ea0a4517e201e84594f67684cbbbebc5e214cda3a5e6755b2752103942b71443a5fe81ab9713165763ee91968759c20ad5b0cd9a210e72474070e2668ac00000000) after 5 blocks
lightningd-1 2022-08-11T16:11:53.516Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: billboard: 3 outputs unresolved: in 5 blocks will spend DELAYED_OUTPUT_TO_US (67107d17c0953fd6b08b5e72ff46af1b696102c575740a2296d22eae6a093ca5:1) using OUR_DELAYED_RETURN_TO_WALLET
lightningd-1 2022-08-11T16:11:53.522Z DEBUG   plugin-bookkeeper: coin_move 2 (to_them) 4000000msat -0msat chain_mvt 1660234313
lightningd-1 2022-08-11T16:11:53.529Z DEBUG   lightningd: Adding block 106: 7154aee46c83587694d9a29f42dc45c645eaaed6356fecc68970e7873a68e808
lightningd-1 2022-08-11T16:11:53.546Z DEBUG   lightningd: Adding block 107: 56da75fca1bfc7f9a3ae0ed726ca9c804de21ea4b52861fa24e40ece8ffdfa7a
lightningd-1 2022-08-11T16:11:53.565Z DEBUG   lightningd: Adding block 108: 3713fed617be154f6f10ccd8a35d97378da0201539c60f737cc5a81da53f2fa4
lightningd-1 2022-08-11T16:11:53.577Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-chan#1: Got depth change 1->6 for ebe71e3c0de2d778c67355c326cecada813f9f61b58484c70f147482ff144c01
lightningd-1 2022-08-11T16:11:53.577Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-chan#1: Funding tx ebe71e3c0de2d778c67355c326cecada813f9f61b58484c70f147482ff144c01 depth 6 of 1
lightningd-1 2022-08-11T16:11:53.577Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-chan#1: Funding tx ebe71e3c0de2d778c67355c326cecada813f9f61b58484c70f147482ff144c01 confirmed, but peer in state ONCHAIN
lightningd-1 2022-08-11T16:11:53.577Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-chan#1: Got depth change 0->5 for 67107d17c0953fd6b08b5e72ff46af1b696102c575740a2296d22eae6a093ca5
lightningd-1 2022-08-11T16:11:53.577Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-chan#1: attempting update blockheight 014c14ff8274140fc78484b5619f3f81dacace26c35573c678d7e20d3c1ee7ea
lightningd-1 2022-08-11T16:11:53.582Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_NEW_BLOCKHEIGHT_REPLY with 0 fds
lightningd-1 2022-08-11T16:11:53.582Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Got new message WIRE_ONCHAIND_DEPTH
lightningd-1 2022-08-11T16:11:53.582Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Sending 0 missing htlc messages
lightningd-1 2022-08-11T16:11:53.582Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: FUNDING_TRANSACTION/FUNDING_OUTPUT->OUR_UNILATERAL depth 5
lightningd-1 2022-08-11T16:11:53.582Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: OUR_UNILATERAL/OUTPUT_TO_THEM->SELF depth 5
lightningd-1 2022-08-11T16:11:53.582Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Broadcasting OUR_DELAYED_RETURN_TO_WALLET (02000000000101a53c096aae2ed296220a7475c50261691baf46ff725e8bb0d63f95c0177d10670100000000050000000164050f0000000000160014071c49cad2f420f3c805f9f6b98a57269cb14150034730440220465647fd5b0ede0d04a662b9d2b9352d813f3977db7b62ca84150fabd4b442e60220732d713f354c0f0d81ea4d2a6c4e9960ccf97e70c1348b624eca6e381869718701004b6321025f3016168568a796c8271ea0a4517e201e84594f67684cbbbebc5e214cda3a5e6755b2752103942b71443a5fe81ab9713165763ee91968759c20ad5b0cd9a210e72474070e2668ac00000000) to resolve OUR_UNILATERAL/DELAYED_OUTPUT_TO_US
lightningd-1 2022-08-11T16:11:53.583Z DEBUG   lightningd: Broadcasting txid a3ff86e7c6d559bd278b377d8a214469c83f2f77b36ced936ea50eb243490a0f
lightningd-1 2022-08-11T16:11:53.583Z DEBUG   lightningd: sendrawtransaction: 02000000000101a53c096aae2ed296220a7475c50261691baf46ff725e8bb0d63f95c0177d10670100000000050000000164050f0000000000160014071c49cad2f420f3c805f9f6b98a57269cb14150034730440220465647fd5b0ede0d04a662b9d2b9352d813f3977db7b62ca84150fabd4b442e60220732d713f354c0f0d81ea4d2a6c4e9960ccf97e70c1348b624eca6e381869718701004b6321025f3016168568a796c8271ea0a4517e201e84594f67684cbbbebc5e214cda3a5e6755b2752103942b71443a5fe81ab9713165763ee91968759c20ad5b0cd9a210e72474070e2668ac00000000
lightningd-1 2022-08-11T16:11:53.587Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: billboard: 3 outputs unresolved: waiting confirmation that we spent DELAYED_OUTPUT_TO_US (67107d17c0953fd6b08b5e72ff46af1b696102c575740a2296d22eae6a093ca5:1) using OUR_DELAYED_RETURN_TO_WALLET
lightningd-1 2022-08-11T16:11:53.594Z DEBUG   plugin-bcli: sendrawtx exit 0 (bitcoin-cli -regtest -datadir=/tmp/ltests-gecvmt23/test_bookkeeping_closing_subsat_htlcs_1/lightning-1/ -rpcport=37455 -rpcuser=... -rpcpassword=... sendrawtransaction 02000000000101a53c096aae2ed296220a7475c50261691baf46ff725e8bb0d63f95c0177d10670100000000050000000164050f0000000000160014071c49cad2f420f3c805f9f6b98a57269cb14150034730440220465647fd5b0ede0d04a662b9d2b9352d813f3977db7b62ca84150fabd4b442e60220732d713f354c0f0d81ea4d2a6c4e9960ccf97e70c1348b624eca6e381869718701004b6321025f3016168568a796c8271ea0a4517e201e84594f67684cbbbebc5e214cda3a5e6755b2752103942b71443a5fe81ab9713165763ee91968759c20ad5b0cd9a210e72474070e2668ac00000000) 
lightningd-2 2022-08-11T16:12:09.727Z DEBUG   lightningd: Adding block 109: 6e2d8ca62b50f66adbf9409a162cde20d83691e5047da301b21c6675b42aad99
lightningd-2 2022-08-11T16:12:09.727Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: Got UTXO spend for 67107d17c0953fd6b08b5e72ff46af1b696102c575740a2296d22eae6a093ca5:1: a3ff86e7c6d559bd278b377d8a214469c83f2f77b36ced936ea50eb243490a0f
lightningd-2 2022-08-11T16:12:09.733Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: Got new message WIRE_ONCHAIND_SPENT
lightningd-2 2022-08-11T16:12:09.733Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: Notified about tx 67107d17c0953fd6b08b5e72ff46af1b696102c575740a2296d22eae6a093ca5 output 1 spend, but we don't care
lightningd-2 2022-08-11T16:12:09.733Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: billboard: All outputs resolved: waiting 95 more blocks before forgetting channel
lightningd-2 2022-08-11T16:12:09.746Z DEBUG   lightningd: Adding block 110: 3db675f916d5d1378fb85a4c0ffe51445ec607cc89b324ebf2322eda9c997a5d
....
4e0f8a5efd621d3818d68e719ea1312399d39481a56469df18e905fe540f9024
lightningd-2 2022-08-11T16:12:11.237Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: Got depth change 5->85 for 67107d17c0953fd6b08b5e72ff46af1b696102c575740a2296d22eae6a093ca5
lightningd-2 2022-08-11T16:12:11.237Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: attempting update blockheight 014c14ff8274140fc78484b5619f3f81dacace26c35573c678d7e20d3c1ee7ea
lightningd-2 2022-08-11T16:12:11.237Z DEBUG   lightningd: sendrawtransaction: 02000000000101014c14ff8274140fc78484b5619f3f81dacace26c35573c678d7e20d3c1ee7eb01000000009db0e28002a00f00000000000022002039b989a62357b0ac389ed364aec6c165e5aaebf5b4e3c1bd9e0c06b9259eeb5a83130f0000000000160014e89954fac8f7a2dce51e095d7beb5271c3f7da56040047304402202d4187615e7160a34b6564dc504bbfe3432ba2e77d46ed9459eff59482dd8ddc0220558ed6ce6003a4cb830712038f721bfd38f0729541a58e6926b30be56faef3e50147304402205d7a2a7a3bfcc5cac09c5c3c4f952a8831f95c3bb6ecca10de8c14a7260682b5022028fb6c321279a9558cf5de16c9613bdd9ab34f9db3b33c5a57a3ec3dc637e1d50147522102324266de8403b3ab157a09f1f784d587af61831c998c151bcc21bb74c2b2314b2102e3bd38009866c9da8ec4aa99cc4ea9c6c0dd46df15c61ef0ce1f271291714e5752ae9c3ed620
lightningd-2 2022-08-11T16:12:11.241Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_NEW_BLOCKHEIGHT_REPLY with 0 fds
lightningd-2 2022-08-11T16:12:11.241Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: Got new message WIRE_ONCHAIND_DEPTH
lightningd-2 2022-08-11T16:12:11.242Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: FUNDING_TRANSACTION/FUNDING_OUTPUT->THEIR_UNILATERAL depth 85
lightningd-2 2022-08-11T16:12:11.242Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: THEIR_UNILATERAL/OUTPUT_TO_US->SELF depth 85
lightningd-2 2022-08-11T16:12:11.242Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: THEIR_UNILATERAL/DELAYED_OUTPUT_TO_THEM->SELF depth 85
lightningd-2 2022-08-11T16:12:11.242Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: billboard: All outputs resolved: waiting 15 more blocks before forgetting channel
lightningd-2 2022-08-11T16:12:11.248Z DEBUG   plugin-bcli: sendrawtx exit 25 (bitcoin-cli -regtest -datadir=/tmp/ltests-gecvmt23/test_bookkeeping_closing_subsat_htlcs_1/lightning-2/ -rpcport=53229 -rpcuser=... -rpcpassword=... sendrawtransaction 02000000000101014c14ff8274140fc78484b5619f3f81dacace26c35573c678d7e20d3c1ee7eb01000000009db0e28002a00f00000000000022002039b989a62357b0ac389ed364aec6c165e5aaebf5b4e3c1bd9e0c06b9259eeb5a83130f0000000000160014e89954fac8f7a2dce51e095d7beb5271c3f7da56040047304402202d4187615e7160a34b6564dc504bbfe3432ba2e77d46ed9459eff59482dd8ddc0220558ed6ce6003a4cb830712038f721bfd38f0729541a58e6926b30be56faef3e50147304402205d7a2a7a3bfcc5cac09c5c3c4f952a8831f95c3bb6ecca10de8c14a7260682b5022028fb6c321279a9558cf5de16c9613bdd9ab34f9db3b33c5a57a3ec3dc637e1d50147522102324266de8403b3ab157a09f1f784d587af61831c998c151bcc21bb74c2b2314b2102e3bd38009866c9da8ec4aa99cc4ea9c6c0dd46df15c61ef0ce1f271291714e5752ae9c3ed620) error code: -25\nerror message:\nbad-txns-inputs-missingorspent
lightningd-2 2022-08-11T16:12:11.248Z DEBUG   lightningd: Expected error broadcasting tx 02000000000101014c14ff8274140fc78484b5619f3f81dacace26c35573c678d7e20d3c1ee7eb01000000009db0e28002a00f00000000000022002039b989a62357b0ac389ed364aec6c165e5aaebf5b4e3c1bd9e0c06b9259eeb5a83130f0000000000160014e89954fac8f7a2dce51e095d7beb5271c3f7da56040047304402202d4187615e7160a34b6564dc504bbfe3432ba2e77d46ed9459eff59482dd8ddc0220558ed6ce6003a4cb830712038f721bfd38f0729541a58e6926b30be56faef3e50147304402205d7a2a7a3bfcc5cac09c5c3c4f952a8831f95c3bb6ecca10de8c14a7260682b5022028fb6c321279a9558cf5de16c9613bdd9ab34f9db3b33c5a57a3ec3dc637e1d50147522102324266de8403b3ab157a09f1f784d587af61831c998c151bcc21bb74c2b2314b2102e3bd38009866c9da8ec4aa99cc4ea9c6c0dd46df15c61ef0ce1f271291714e5752ae9c3ed620: error code: -25\nerror message:\nbad-txns-inputs-missingorspent
lightningd-1 2022-08-11T16:12:23.595Z DEBUG   lightningd: Adding block 109: 6e2d8ca62b50f66adbf9409a162cde20d83691e5047da301b21c6675b42aad99
lightningd-1 2022-08-11T16:12:23.596Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-chan#1: Got UTXO spend for 67107d17c0953fd6b08b5e72ff46af1b696102c575740a2296d22eae6a093ca5:1: a3ff86e7c6d559bd278b377d8a214469c83f2f77b36ced936ea50eb243490a0f
lightningd-1 2022-08-11T16:12:23.597Z DEBUG   wallet: Owning output 0 984420sat (SEGWIT) txid a3ff86e7c6d559bd278b377d8a214469c83f2f77b36ced936ea50eb243490a0f CONFIRMED
lightningd-1 2022-08-11T16:12:23.604Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Got new message WIRE_ONCHAIND_SPENT
lightningd-1 2022-08-11T16:12:23.604Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Resolved OUR_UNILATERAL/DELAYED_OUTPUT_TO_US by our proposal OUR_DELAYED_RETURN_TO_WALLET (a3ff86e7c6d559bd278b377d8a214469c83f2f77b36ced936ea50eb243490a0f)
lightningd-1 2022-08-11T16:12:23.604Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: billboard: All outputs resolved: waiting 100 more blocks before forgetting channel
lightningd-1 2022-08-11T16:12:23.614Z DEBUG   plugin-bookkeeper: coin_move 2 (deposit) 984420000msat -0msat chain_mvt 1660234343
lightningd-1 2022-08-11T16:12:23.618Z DEBUG   lightningd: Adding block 110: 3db675f916d5d1378fb85a4c0ffe51445ec607cc89b324ebf2322eda9c997a5d
lightningd-1 2022-08-11T16:12:23.624Z DEBUG   plugin-bookkeeper: coin_move 2 (delayed_to_us) 988035000msat -0msat chain_mvt 1660234343
lightningd-1 2022-08-11T16:12:23.624Z DEBUG   plugin-bookkeeper: coin_move 2 (to_wallet) 0msat -988035000msat chain_mvt 1660234343
lightningd-1 2022-08-11T16:12:23.638Z DEBUG   lightningd: Adding block 111: 
....
lightningd-1 2022-08-11T16:12:25.092Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Got new message WIRE_ONCHAIND_DEPTH
lightningd-1 2022-08-11T16:12:25.093Z DEBUG   gossipd: REPLY WIRE_GOSSIPD_NEW_BLOCKHEIGHT_REPLY with 0 fds
lightningd-1 2022-08-11T16:12:25.093Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: OUR_UNILATERAL/DELAYED_OUTPUT_TO_US->OUR_DELAYED_RETURN_TO_WALLET depth 80
lightningd-1 2022-08-11T16:12:25.093Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: billboard: All outputs resolved: waiting 95 more blocks before forgetting channel
lightningd-1 2022-08-11T16:12:25.093Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Got new message WIRE_ONCHAIND_DEPTH
lightningd-1 2022-08-11T16:12:25.093Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: FUNDING_TRANSACTION/FUNDING_OUTPUT->OUR_UNILATERAL depth 85
lightningd-1 2022-08-11T16:12:25.093Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: OUR_UNILATERAL/OUTPUT_TO_THEM->SELF depth 85
lightningd-1 2022-08-11T16:12:25.093Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: billboard: All outputs resolved: waiting 20 more blocks before forgetting channel
Flightningd-1 2022-08-11T16:12:26.363Z UNUSUAL lightningd: JSON-RPC shutdown
lightningd-1 2022-08-11T16:12:26.363Z DEBUG   lightningd: io_break: start_json_stream
lightningd-1 2022-08-11T16:12:26.363Z DEBUG   lightningd: io_loop_with_timers: main
lightningd-1 2022-08-11T16:12:26.363Z DEBUG   connectd: Shutting down
lightningd-1 2022-08-11T16:12:26.365Z DEBUG   gossipd: Shutting down
lightningd-2 2022-08-11T16:12:26.365Z DEBUG   connectd: drain_peer
lightningd-2 2022-08-11T16:12:26.365Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-lightningd: peer_disconnect_done
lightningd-2 2022-08-11T16:12:26.365Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-lightningd: Not reconnecting: no active channel
lightningd-2 2022-08-11T16:12:26.365Z DEBUG   connectd: maybe_free_peer freeing peer!
lightningd-2 2022-08-11T16:12:26.365Z DEBUG   plugin-funder: Cleaning up inflights for peer id 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518
lightningd-1 2022-08-11T16:12:26.366Z DEBUG   hsmd: Shutting down
lightningd-1 2022-08-11T16:12:27.366Z DEBUG   022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Status closed, but not exited. Killing
lightningd-1 2022-08-11T16:12:27.368Z DEBUG   plugin-autoclean: Killing plugin: exited during normal operation
lightningd-1 2022-08-11T16:12:27.368Z DEBUG   plugin-chanbackup: Killing plugin: exited during normal operation
lightningd-1 2022-08-11T16:12:27.368Z DEBUG   plugin-bcli: Killing plugin: exited during normal operation
lightningd-1 2022-08-11T16:12:27.368Z DEBUG   plugin-commando: Killing plugin: exited during normal operation
lightningd-1 2022-08-11T16:12:27.368Z DEBUG   plugin-funder: Killing plugin: exited during normal operation
lightningd-1 2022-08-11T16:12:27.368Z DEBUG   plugin-topology: Killing plugin: exited during normal operation
lightningd-1 2022-08-11T16:12:27.368Z DEBUG   plugin-keysend: Killing plugin: exited during normal operation
lightningd-1 2022-08-11T16:12:27.368Z DEBUG   plugin-offers: Killing plugin: exited during normal operation
lightningd-1 2022-08-11T16:12:27.369Z DEBUG   plugin-pay: Killing plugin: exited during normal operation
lightningd-1 2022-08-11T16:12:27.369Z DEBUG   plugin-txprepare: Killing plugin: exited during normal operation
lightningd-1 2022-08-11T16:12:27.369Z DEBUG   plugin-spenderp: Killing plugin: exited during normal operation
lightningd-1 2022-08-11T16:12:27.369Z DEBUG   lightningd: io_break: destroy_plugin
lightningd-1 2022-08-11T16:12:27.369Z DEBUG   plugin-bookkeeper: Killing plugin: exited during normal operation
lightningd-1 2022-08-11T16:12:27.369Z DEBUG   lightningd: Command returned result after jcon close
lightningd-2 2022-08-11T16:12:27.374Z UNUSUAL lightningd: JSON-RPC shutdown
lightningd-2 2022-08-11T16:12:27.375Z DEBUG   lightningd: io_break: start_json_stream
lightningd-2 2022-08-11T16:12:27.375Z DEBUG   lightningd: io_loop_with_timers: main
lightningd-2 2022-08-11T16:12:27.375Z DEBUG   connectd: Shutting down
lightningd-2 2022-08-11T16:12:27.376Z DEBUG   gossipd: Shutting down
lightningd-2 2022-08-11T16:12:27.377Z DEBUG   hsmd: Shutting down
lightningd-2 2022-08-11T16:12:28.377Z DEBUG   0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: Status closed, but not exited. Killing
lightningd-2 2022-08-11T16:12:28.379Z DEBUG   plugin-autoclean: Killing plugin: exited during normal operation
lightningd-2 2022-08-11T16:12:28.379Z DEBUG   plugin-chanbackup: Killing plugin: exited during normal operation
lightningd-2 2022-08-11T16:12:28.379Z DEBUG   plugin-bcli: Killing plugin: exited during normal operation
lightningd-2 2022-08-11T16:12:28.379Z DEBUG   plugin-commando: Killing plugin: exited during normal operation
lightningd-2 2022-08-11T16:12:28.379Z DEBUG   plugin-funder: Killing plugin: exited during normal operation
lightningd-2 2022-08-11T16:12:28.379Z DEBUG   plugin-topology: Killing plugin: exited during normal operation
lightningd-2 2022-08-11T16:12:28.379Z DEBUG   plugin-keysend: Killing plugin: exited during normal operation
lightningd-2 2022-08-11T16:12:28.379Z DEBUG   plugin-offers: Killing plugin: exited during normal operation
lightningd-2 2022-08-11T16:12:28.379Z DEBUG   plugin-pay: Killing plugin: exited during normal operation
lightningd-2 2022-08-11T16:12:28.380Z DEBUG   plugin-txprepare: Killing plugin: exited during normal operation
lightningd-2 2022-08-11T16:12:28.380Z DEBUG   plugin-spenderp: Killing plugin: exited during normal operation
lightningd-2 2022-08-11T16:12:28.380Z DEBUG   lightningd: io_break: destroy_plugin
lightningd-2 2022-08-11T16:12:28.380Z DEBUG   plugin-bookkeeper: Killing plugin: exited during normal operation
lightningd-2 2022-08-11T16:12:28.380Z DEBUG   lightningd: Command returned result after jcon close
Leaving base_dir /tmp/ltests-gecvmt23 intact, it still has test sub-directories with failure details: ['test_bookkeeping_closing_subsat_htlcs_1']


================================================================================================================================== FAILURES ===================================================================================================================================
____________________________________________________________________________________________________________________ test_bookkeeping_closing_subsat_htlcs ____________________________________________________________________________________________________________________

node_factory = <pyln.testing.utils.NodeFactory object at 0x7f3e5bdf2908>, bitcoind = <pyln.testing.utils.BitcoinD object at 0x7f3e5bde6fd0>
chainparams = {'bip173_prefix': 'bcrt', 'chain_hash': '06226e46111a0b59caaf126043eb5bbf28c34f3a5e332a1fc7b2b73cf188910f', 'elements': False, 'example_addr': 'bcrt1qeyyk6sl5pr49ycpqyckvmttus5ttj25pd0zpvg', ...}

    @unittest.skipIf(TEST_NETWORK != 'regtest', "fixme: broadcast fails, dusty")
    def test_bookkeeping_closing_subsat_htlcs(node_factory, bitcoind, chainparams):
        """Test closing balances when HTLCs are: sub 1-satoshi"""
        l1, l2 = node_factory.line_graph(2)
    
        l1.pay(l2, 111)
        l1.pay(l2, 222)
        l1.pay(l2, 4000000)
    
        l2.stop()
        l1.rpc.close(l2.info['id'], 1)
        bitcoind.generate_block(5, wait_for_mempool=1)
    
        l2.start()
        sync_blockheight(bitcoind, [l1])
        l1.daemon.wait_for_log('Broadcasting OUR_DELAYED_RETURN_TO_WALLET')
        bitcoind.generate_block(80)
    
        sync_blockheight(bitcoind, [l1, l2])
        evs = l1.rpc.bkpr_listaccountevents()['events']
        # check that closing equals onchain deposits + fees
        close = find_first_tag(evs, 'channel_close')
        delayed_to = find_first_tag(evs, 'delayed_to_us')
        fees = find_tags(evs, 'onchain_fee')
        close_fee = [e for e in fees if e['txid'] == close['txid']]
>       assert len(close_fee) == 1
E       assert 0 == 1
E        +  where 0 = len([])

tests/test_bookkeeper.py:99: AssertionError
=========================================================================================================================== short test summary info ===========================================================================================================================
FAILED tests/test_bookkeeper.py::test_bookkeeping_closing_subsat_htlcs - assert 0 == 1
================================================================================================================ 1 failed, 525 deselected in 130.15s (0:02:10) =

[SimonVrouwe]

When I run make check-units it stops here

plugins/bkpr/test/run-recorder.c:700: test condition failed
make: *** [Makefile:730: unittest/plugins/bkpr/test/run-recorder] Error 1

edit: maybe relevant

sqlite3 --version
3.27.2 2019-02-25 16:06:06 bd49a8271d650fa89e446b42e513b595a717b9212c91dd384aab871fc1d0alt1

uname -a
Linux gamepc 4.19.0-21-amd64 #1 SMP Debian 4.19.249-2 (2022-06-30) x86_64 GNU/Linux

gcc --version
gcc (Debian 8.3.0-6) 8.3.0

more config.vars 
HAVE_32BIT_OFF_T=0
HAVE_ALIGNOF=1
HAVE_ASPRINTF=1
HAVE_ATTRIBUTE_COLD=1
HAVE_ATTRIBUTE_CONST=1
HAVE_ATTRIBUTE_DEPRECATED=0
HAVE_ATTRIBUTE_NONNULL=1
HAVE_ATTRIBUTE_RETURNS_NONNULL=1
HAVE_ATTRIBUTE_SENTINEL=1
HAVE_ATTRIBUTE_PURE=1
HAVE_ATTRIBUTE_MAY_ALIAS=1
HAVE_ATTRIBUTE_NORETURN=1
HAVE_ATTRIBUTE_PRINTF=1
HAVE_ATTRIBUTE_UNUSED=1
HAVE_ATTRIBUTE_USED=1
HAVE_BACKTRACE=1
HAVE_BIG_ENDIAN=0
HAVE_BSWAP_64=1
HAVE_BUILTIN_CHOOSE_EXPR=1
HAVE_BUILTIN_CLZ=1
HAVE_BUILTIN_CLZL=1
HAVE_BUILTIN_CLZLL=1
HAVE_BUILTIN_CTZ=1
HAVE_BUILTIN_CTZL=1
HAVE_BUILTIN_CTZLL=1
HAVE_BUILTIN_CONSTANT_P=1
HAVE_BUILTIN_EXPECT=1
HAVE_BUILTIN_FFS=1
HAVE_BUILTIN_FFSL=1
HAVE_BUILTIN_FFSLL=1
HAVE_BUILTIN_POPCOUNT=1
HAVE_BUILTIN_POPCOUNTL=1
HAVE_BUILTIN_POPCOUNTLL=1
HAVE_BUILTIN_TYPES_COMPATIBLE_P=1
HAVE_ICCARM_INTRINSICS=0
HAVE_BYTESWAP_H=1
HAVE_CLOCK_GETTIME=1
HAVE_CLOCK_GETTIME_IN_LIBRT=0
HAVE_COMPOUND_LITERALS=1
HAVE_FCHDIR=1
HAVE_ERR_H=1
HAVE_FILE_OFFSET_BITS=0
HAVE_FOR_LOOP_DECLARATION=1
HAVE_FLEXIBLE_ARRAY_MEMBER=1
HAVE_GETPAGESIZE=1
HAVE_ISBLANK=1
HAVE_LITTLE_ENDIAN=1
HAVE_MEMMEM=1
HAVE_MEMRCHR=1
HAVE_MMAP=1
HAVE_PROC_SELF_MAPS=1
HAVE_QSORT_R_PRIVATE_LAST=1
HAVE_STRUCT_TIMESPEC=1
HAVE_SECTION_START_STOP=1
HAVE_STACK_GROWS_UPWARDS=0
HAVE_STATEMENT_EXPR=1
HAVE_SYS_FILIO_H=0
HAVE_SYS_TERMIOS_H=1
HAVE_SYS_UNISTD_H=1
HAVE_TYPEOF=1
HAVE_UNALIGNED_ACCESS=1
HAVE_UTIME=1
HAVE_WARN_UNUSED_RESULT=1
HAVE_OPENMP=1
HAVE_VALGRIND_MEMCHECK_H=1
HAVE_UCONTEXT=1
HAVE_POINTER_SAFE_MAKECONTEXT=1
HAVE_BUILTIN_CPU_SUPPORTS=1
HAVE_CLOSEFROM=0
HAVE_F_CLOSEM=0
HAVE_NR_CLOSE_RANGE=0
HAVE_F_MAXFD=0
HAVE_GOOD_LIBSODIUM=1
HAVE_SQLITE3_EXPANDED_SQL=1
HAVE_SQLITE3=1
HAVE_POSTGRES=1
HAVE_GCC=1
HAVE_MODERN_GCC=1
HAVE_PWRITEV=1
PREFIX=/usr/local
CC=cc
CONFIGURATOR_CC=cc
CWARNFLAGS=-Wall -Wundef -Wmissing-prototypes -Wmissing-declarations -Wstrict-prototypes -Wold-style-definition -Werror -Wno-maybe-uninitialized
CDEBUGFLAGS=-std=gnu11 -g -fstack-protector-strong
COPTFLAGS=-Og
SQLITE3_CFLAGS=
SQLITE3_LDLIBS=-lsqlite3
POSTGRES_INCLUDE=-I/usr/include/postgresql
POSTGRES_LDLIBS=-L/usr/lib/x86_64-linux-gnu -lpq
VALGRIND=1
DEVELOPER=0
EXPERIMENTAL_FEATURES=0
COMPAT=1
PYTEST=python3 -m pytest
STATIC=0
ASAN=0
UBSAN=0
TEST_NETWORK=regtest
HAVE_PYTHON3_MAKO=1
SHA256SUM=sha256sum
FUZZING=0
RUST=1

[SimonVrouwe]

I think this is caused by outdated version of sqlite3
On another system with sqlite3 --version 3.34.1 2021-01-20 14:10:07 the make check-units all pass.

Will close this.

[wtogami]

I think this is caused by outdated version of sqlite3 On another system with sqlite3 --version 3.34.1 2021-01-20 14:10:07 the make check-units all pass.

Will close this.

Hold on ... If it builds against versions of a dependency but results in broken code we need to know what versions are safe and document that. Configure could also refuse to build in such cases?

[SimonVrouwe]

It has something to do with sqlite3, but still not sure what exactly. I think the sqlite3 versions are the same (oddly the last three letters of the hash differ).

sqlite3 --version
3.34.1 2021-01-20 14:10:07 10e20c0b43500cfb9bbc0eaa061c57514f715d87238f4d835880cd846b9ebd1f
sqlite3 --version
3.34.1 2021-01-20 14:10:07 10e20c0b43500cfb9bbc0eaa061c57514f715d87238f4d835880cd846b9ealt1

After some digging and comparing side-by-side the result of plugins/bkpr/test/run-recorder on a good system and on failing system, with below debug code added:

git diff -- plugins/bkpr/recorder.c
diff --git a/plugins/bkpr/recorder.c b/plugins/bkpr/recorder.c
index 79a70f8b6..62f8e2e9f 100644
--- a/plugins/bkpr/recorder.c
+++ b/plugins/bkpr/recorder.c
@@ -72,6 +72,8 @@ static struct chain_event **find_chain_events(const tal_t *ctx,
        struct chain_event **results;
 
        db_query_prepared(stmt);
+       if (stmt->error)
+               db_fatal("SiVr %s", stmt->error);
        results = tal_arr(ctx, struct chain_event *, 0);
        while (db_step(stmt)) {
                struct chain_event *e = stmt2chain_event(results, stmt);

On the failing system (only) I get 4x ...near "NULLS": syntax error:

./run-recorder 
plugins/bkpr/test/run-recorder.c:624: SiVr plugins/bkpr/recorder.c:251: SELECT  e.id, e.account_id, a.name, e.origin, e.tag, e.credit, e.debit, e.output_value, e.currency, e.timestamp, e.blockheight, e.utxo_txid, e.outnum, e.spending_txid, e.payment_id, e.ignored, e.stealable, e.ev_desc FROM chain_events e LEFT OUTER JOIN accounts a ON e.account_id = a.id WHERE e.utxo_txid = ? ORDER BY   e.utxo_txid, e.outnum, e.spending_txid NULLS FIRST, e.blockheight: near "NULLS": syntax error

Which is this stmt

lightning/plugins/bkpr/recorder.c

Lines 216 to 253 in 4e7f89f

	static struct chain_event **find_txos_for_tx(const tal_t *ctx,
	struct db *db,
	struct bitcoin_txid *txid)
	{
	struct db_stmt *stmt;
	stmt = db_prepare_v2(db, SQL("SELECT"
	" e.id"
	", e.account_id"
	", a.name"
	", e.origin"
	", e.tag"
	", e.credit"
	", e.debit"
	", e.output_value"
	", e.currency"
	", e.timestamp"
	", e.blockheight"
	", e.utxo_txid"
	", e.outnum"
	", e.spending_txid"
	", e.payment_id"
	", e.ignored"
	", e.stealable"
	", e.ev_desc"
	" FROM chain_events e"
	" LEFT OUTER JOIN accounts a"
	" ON e.account_id = a.id"
	" WHERE e.utxo_txid = ?"
	" ORDER BY "
	" e.utxo_txid"
	", e.outnum"
	", e.spending_txid NULLS FIRST"
	", e.blockheight"));
	db_bind_txid(stmt, 0, txid);
	return find_chain_events(ctx, take(stmt));
	}

[SimonVrouwe]

The NULL FIRST syntax was added in v3.30.1 https://sqlite.org/releaselog/3_30_1.html

What version is installed on my (failing) system and which library version used for the build still seem to differ.
Opening the db from run-recorder manually:

sqlite3 --header --line /tmp/lacct-db-QFxycA
SQLite version 3.34.1 2021-01-20 14:10:07
Enter ".help" for usage hints.
sqlite> SELECT sqlite_version();
sqlite_version() = 3.34.1
sqlite> .dbinfo
database page size:  4096
write format:        1
read format:         1
reserved bytes:      0
file change counter: 6
database page count: 9
freelist page count: 0
schema cookie:       14
schema format:       4
default cache size:  0
autovacuum top root: 0
incremental vacuum:  0
text encoding:       1 (utf8)
user version:        0
application id:      0
software version:    3027002
number of tables:    6
number of indexes:   2
number of triggers:  0
number of views:     0
schema size:         1240
data version         1
sqlite> 

Note the software version: 3027002 vs SQLite version 3.34.1 2021-01-20 14:10:07 vs sqlite_version() = 3.34.1

My failing system is probably a bit of a mess with packages.
But maybe a build check can be added to check the version? Or print stmt->error can also be helpful.

[niftynei]

Oof ok we need to fix this before we do the final release for v0.12. Thanks for digging into this, turns out it was silently causing problems on the machine where I'm running my node. 🤦

[niftynei]

@SimonVrouwe can you check if the patch i pushed fixes this issue for you?

[SimonVrouwe]

@SimonVrouwe can you check if the patch i pushed fixes this issue for you?

Yes, all tests pass. Thanks.