# Debug bookkeeper plugin ## Bad commit `200c88fcb98f5e3631d19e0b4432fba9e97dbf66` ``` lightningd-2 2022-11-15T19:19:31.349Z DEBUG plugin-bookkeeper: Setting up database at sqlite3://accounts.sqlite3 lightningd-2 2022-11-15T19:19:31.349Z INFO plugin-bookkeeper: Creating database lightningd-2 2022-11-15T19:19:31.397Z DEBUG plugin-bookkeeper: account wallet has balance 0msat lightningd-2 2022-11-15T19:19:31.397Z DEBUG plugin-bookkeeper: Snapshot balance does not equal ondisk reported 0msat, off by (+0msat/-0msat) (account wallet) Logging journal entry. lightningd-2 2022-11-15T19:19:31.397Z INFO plugin-bookkeeper: account wallet not found, adding along with new balance lightningd-2 2022-11-15T19:19:31.397Z DEBUG plugin-bookkeeper: Snapshot balances updated lightningd-2 2022-11-15T19:19:33.555Z DEBUG plugin-bookkeeper: coin_move 2 (channel_open) 0msat -0msat chain_mvt 1668539973 lightningd-2 2022-11-15T19:19:42.655Z DEBUG plugin-bookkeeper: coin_move 2 (invoice) 111msat -0msat channel_mvt 1668539982 lightningd-2 2022-11-15T19:19:43.885Z DEBUG plugin-bookkeeper: coin_move 2 (invoice) 222msat -0msat channel_mvt 1668539983 lightningd-2 2022-11-15T19:19:45.074Z DEBUG plugin-bookkeeper: Killing plugin: exited during normal operation lightningd-2 2022-11-15T19:19:46.936Z DEBUG plugin-bookkeeper: Setting up database at sqlite3://accounts.sqlite3 lightningd-2 2022-11-15T19:19:46.989Z DEBUG plugin-bookkeeper: coin_move 2 (channel_close) 0msat -333msat chain_mvt 1668539986 lightningd-2 2022-11-15T19:19:47.022Z DEBUG plugin-bookkeeper: coin_move 2 (deposit) 4000000msat -0msat chain_mvt 1668539986 lightningd-2 2022-11-15T19:19:47.023Z DEBUG plugin-bookkeeper: coin_move 2 (to_them) 988035000msat -0msat chain_mvt 1668539987 lightningd-2 2022-11-15T19:19:47.056Z DEBUG plugin-bookkeeper: account wallet has balance 4000000msat lightningd-2 2022-11-15T19:19:47.056Z DEBUG plugin-bookkeeper: Snapshot balances updated lightningd-2 2022-11-15T19:19:50.220Z DEBUG plugin-bookkeeper: Killing plugin: exited during normal operation ``` ## Good commit on master ``` ➜ ~ cat /tmp/ltests-1a5_m3b1/test_bookkeeping_closing_subsat_htlcs_1/lightning-2/log | grep plugin-bookkeeper lightningd-2 2022-11-15T21:04:20.703Z DEBUG plugin-bookkeeper: Setting up database at sqlite3://accounts.sqlite3 lightningd-2 2022-11-15T21:04:20.703Z INFO plugin-bookkeeper: Creating database lightningd-2 2022-11-15T21:04:20.756Z DEBUG plugin-bookkeeper: account wallet has balance 0msat lightningd-2 2022-11-15T21:04:20.756Z DEBUG plugin-bookkeeper: Snapshot balance does not equal ondisk reported 0msat, off by (+0msat/-0msat) (account wallet) Logging journal entry. lightningd-2 2022-11-15T21:04:20.756Z INFO plugin-bookkeeper: account wallet not found, adding along with new balance lightningd-2 2022-11-15T21:04:20.756Z DEBUG plugin-bookkeeper: Snapshot balances updated lightningd-2 2022-11-15T21:04:22.843Z DEBUG plugin-bookkeeper: coin_move 2 (channel_open) 0msat -0msat chain_mvt 1668546262 lightningd-2 2022-11-15T21:04:32.786Z DEBUG plugin-bookkeeper: coin_move 2 (invoice) 111msat -0msat channel_mvt 1668546272 lightningd-2 2022-11-15T21:04:34.252Z DEBUG plugin-bookkeeper: coin_move 2 (invoice) 222msat -0msat channel_mvt 1668546274 lightningd-2 2022-11-15T21:04:35.739Z DEBUG plugin-bookkeeper: coin_move 2 (invoice) 4000000msat -0msat channel_mvt 1668546275 lightningd-2 2022-11-15T21:04:35.772Z DEBUG plugin-bookkeeper: Killing plugin: exited during normal operation lightningd-2 2022-11-15T21:04:37.597Z DEBUG plugin-bookkeeper: Setting up database at sqlite3://accounts.sqlite3 lightningd-2 2022-11-15T21:04:37.687Z DEBUG plugin-bookkeeper: coin_move 2 (channel_close) 0msat -4000333msat chain_mvt 1668546277 lightningd-2 2022-11-15T21:04:37.728Z DEBUG plugin-bookkeeper: coin_move 2 (deposit) 4000000msat -0msat chain_mvt 1668546277 lightningd-2 2022-11-15T21:04:37.728Z DEBUG plugin-bookkeeper: coin_move 2 (to_them) 988035000msat -0msat chain_mvt 1668546277 lightningd-2 2022-11-15T21:04:37.805Z DEBUG plugin-bookkeeper: account wallet has balance 4000000msat lightningd-2 2022-11-15T21:04:37.805Z DEBUG plugin-bookkeeper: Snapshot balances updated lightningd-2 2022-11-15T21:04:43.272Z DEBUG plugin-bookkeeper: Killing plugin: exited during normal operation ➜ ~ ``` ## Good full log ``` lightningd-2 2022-11-15T23:02:42.706Z DEBUG lightningd: Adding block 106: 2376c2ae06598ee2bfd300c863b07827452ae80255e64e5e81b39b4ce63f48d3 lightningd-2 2022-11-15T23:02:42.716Z DEBUG plugin-bookkeeper: coin_move 2 (deposit) 4000000msat -0msat chain_mvt 1668553362 lightningd-2 2022-11-15T23:02:42.716Z DEBUG plugin-bookkeeper: coin_move 2 (to_them) 988035000msat -0msat chain_mvt 1668553362 lightningd-2 2022-11-15T23:02:42.721Z DEBUG lightningd: Adding block 107: 69cedf32b9497883aefea420bb5b670ccae354029641a83c1de1fb766a543311 lightningd-2 2022-11-15T23:02:42.735Z DEBUG lightningd: Adding block 108: 2fcbb277272c3f70a3c7b273bb2082a04026f1b9fd84c25f5bd030b9079c3fe5 lightningd-2 2022-11-15T23:02:42.743Z DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: Got depth change 0->5 for ad9c29733e6f8d0c43f25eb40378bdc2bc9d58a15586edef6c48999f4cf8c475 lightningd-2 2022-11-15T23:02:42.743Z DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: Got depth change 0->6 for 664f4421f9f06d2d9e4c61850131466620ba76e55e2872940c0659a6b71b5a48 lightningd-2 2022-11-15T23:02:42.743Z DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: Funding tx 664f4421f9f06d2d9e4c61850131466620ba76e55e2872940c0659a6b71b5a48 depth 6 of 1 lightningd-2 2022-11-15T23:02:42.744Z DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: Funding tx 664f4421f9f06d2d9e4c61850131466620ba76e55e2872940c0659a6b71b5a48 confirmed, but peer in state ONCHAIN lightningd-2 2022-11-15T23:02:42.744Z DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-chan#1: attempting update blockheight 485a1bb7a659060c9472285ee576ba206646310185614c9e2d6df0f921444f66 lightningd-2 2022-11-15T23:02:42.744Z DEBUG lightningd: sendrawtransaction: 02000000000101485a1bb7a659060c9472285ee576ba206646310185614c9e2d6df0f921444f6600000000009db0e28002a00f00000000000022002039b989a62357b0ac389ed364aec6c165e5aaebf5b4e3c1bd9e0c06b9259eeb5a83130f0000000000160014e89954fac8f7a2dce51e095d7beb5271c3f7da560400473044022041de3d8949d4cac218e5119478af357620d2e94852a856ce158fd85ccc86021f02205fe74b85cc1e04e3dd9af9bf2e2f7b4416753cadefef9c4e90996b6bcfaf3a270147304402205c9c2f9e15b8b4ad02fd7c37cc8312ca2a5458b2735edcd1f961d8fab3d0a7aa02203cc662406149e36aa5e3a32bf2d84a6024be235de9dc1e60960e2164fe5fedca0147522102324266de8403b3ab157a09f1f784d587af61831c998c151bcc21bb74c2b2314b2102e3bd38009866c9da8ec4aa99cc4ea9c6c0dd46df15c61ef0ce1f271291714e5752ae9c3ed620 lightningd-2 2022-11-15T23:02:42.748Z DEBUG gossipd: REPLY WIRE_GOSSIPD_NEW_BLOCKHEIGHT_REPLY with 0 fds lightningd-2 2022-11-15T23:02:42.748Z DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: Got new message WIRE_ONCHAIND_DEPTH lightningd-2 2022-11-15T23:02:42.748Z DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: Sending 0 missing htlc messages lightningd-2 2022-11-15T23:02:42.748Z DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: FUNDING_TRANSACTION/FUNDING_OUTPUT->THEIR_UNILATERAL depth 5 lightningd-2 2022-11-15T23:02:42.748Z DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: THEIR_UNILATERAL/OUTPUT_TO_US->SELF depth 5 lightningd-2 2022-11-15T23:02:42.748Z DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: THEIR_UNILATERAL/DELAYED_OUTPUT_TO_THEM->SELF depth 5 lightningd-2 2022-11-15T23:02:42.748Z DEBUG 0266e4598d1d3c415f572a8488830b60f7e744ed9235eb0b1ba93283b315c03518-onchaind-chan#1: billboard: All outputs resolved: waiting 95 more blocks before forgetting channel lightningd-2 2022-11-15T23:02:42.749Z DEBUG plugin-bookkeeper: account wallet has balance 4000000msat lightningd-2 2022-11-15T23:02:42.749Z DEBUG plugin-bookkeeper: Snapshot balances updated lightningd-2 2022-11-15T23:02:42.755Z DEBUG plugin-bcli: sendrawtx exit 25 (bitcoin-cli -regtest -datadir=/tmp/ltests-9ujwuqul/test_bookkeeping_closing_subsat_htlcs_1/lightning-2/ -rpcport=47235 -rpcuser=... -stdinrpcpass sendrawtransaction 02000000000101485a1bb7a659060c9472285ee576ba206646310185614c9e2d6df0f921444f6600000000009db0e28002a00f00000000000022002039b989a62357b0ac389ed364aec6c165e5aaebf5b4e3c1bd9e0c06b9259eeb5a83130f0000000000160014e89954fac8f7a2dce51e095d7beb5271c3f7da560400473044022041de3d8949d4cac218e5119478af357620d2e94852a856ce158fd85ccc86021f02205fe74b85cc1e04e3dd9af9bf2e2f7b4416753cadefef9c4e90996b6bcfaf3a270147304402205c9c2f9e15b8b4ad02fd7c37cc8312ca2a5458b2735edcd1f961d8fab3d0a7aa02203cc662406149e36aa5e3a32bf2d84a6024be235de9dc1e60960e2164fe5fedca0147522102324266de8403b3ab157a09f1f784d587af61831c998c151bcc21bb74c2b2314b2102e3bd38009866c9da8ec4aa99cc4ea9c6c0dd46df15c61ef0ce1f271291714e5752ae9c3ed620) error code: -25\nerror message:\nbad-txns-inputs-missingorspent lightningd-2 2022-11-15T23:02:42.755Z DEBUG lightningd: Expected error broadcasting tx 02000000000101485a1bb7a659060c9472285ee576ba206646310185614c9e2d6df0f921444f6600000000009db0e28002a00f00000000000022002039b989a62357b0ac389ed364aec6c165e5aaebf5b4e3c1bd9e0c06b9259eeb5a83130f0000000000160014e89954fac8f7a2dce51e095d7beb5271c3f7da560400473044022041de3d8949d4cac218e5119478af357620d2e94852a856ce158fd85ccc86021f02205fe74b85cc1e04e3dd9af9bf2e2f7b4416753cadefef9c4e90996b6bcfaf3a270147304402205c9c2f9e15b8b4ad02fd7c37cc8312ca2a5458b2735edcd1f961d8fab3d0a7aa02203cc662406149e36aa5e3a32bf2d84a6024be235de9dc1e60960e2164fe5fedca0147522102324266de8403b3ab157a09f1f784d587af61831c998c151bcc21bb74c2b2314b2102e3bd38009866c9da8ec4aa99cc4ea9c6c0dd46df15c61ef0ce1f271291714e5752ae9c3ed620: error code: -25\nerror message:\nbad-txns-inputs-missingorspent lightningd-1 2022-11-15T23:02:43.120Z DEBUG lightningd: Adding block 104: 3ea517d17b4b522a8b5962f72c97b8b291534e49ad5da49ab4e35d203f78a60d lightningd-1 2022-11-15T23:02:43.121Z DEBUG 022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-chan#1: Got UTXO spend for 664f4421f9f06d2d9e4c61850131466620ba76e55e2872940c0659a6b71b5a48:0: ad9c29733e6f8d0c43f25eb40378bdc2bc9d58a15586edef6c48999f4cf8c475 lightningd-1 2022-11-15T23:02:43.121Z UNUSUAL 022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-chan#1: Peer permanent failure in AWAITING_UNILATERAL: Funding transaction spent lightningd-1 2022-11-15T23:02:43.122Z DEBUG lightningd: Broadcasting txid ad9c29733e6f8d0c43f25eb40378bdc2bc9d58a15586edef6c48999f4cf8c475 lightningd-1 2022-11-15T23:02:43.123Z DEBUG lightningd: sendrawtransaction: 02000000000101485a1bb7a659060c9472285ee576ba206646310185614c9e2d6df0f921444f6600000000009db0e28002a00f00000000000016001445503fa4b65ade3ffdb1a92057688456c9ffae1383130f0000000000220020be82765fdb17fd5568f2dd31c6cf1aabc620ef338995ec5d9a2f3e42f43ae487040047304402204bb3868bf3b521fd6bf39cabde740de0cf711f6251393dfa95dcf4e2edd294bd02207dd5fa24ca68821b2cb9985f5da1bf1613e9436788f19674bf8fbf7d268134af01473044022067ab1dd0c85fd465baea727a3c5db727f753e9f00c0f3f217274348074c6265c02202b4e2dd365ce01f7e00da585b2ecacda33fc07848acd487ab8a29660afa7e5ea0147522102324266de8403b3ab157a09f1f784d587af61831c998c151bcc21bb74c2b2314b2102e3bd38009866c9da8ec4aa99cc4ea9c6c0dd46df15c61ef0ce1f271291714e5752ae9c3ed620 lightningd-1 2022-11-15T23:02:43.123Z INFO 022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-chan#1: State changed from AWAITING_UNILATERAL to FUNDING_SPEND_SEEN lightningd-1 2022-11-15T23:02:43.125Z DEBUG 022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: pid 895995, msgfd 54 lightningd-1 2022-11-15T23:02:43.125Z DEBUG 022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-chan#1: channel->static_remotekey_start[LOCAL] 0 lightningd-1 2022-11-15T23:02:43.135Z DEBUG hsmd: Client: Received message 5 from client lightningd-1 2022-11-15T23:02:43.135Z DEBUG gossipd: Deleting channel 103x1x0 due to the funding outpoint being spent lightningd-1 2022-11-15T23:02:43.135Z DEBUG hsmd: new_client: 1 lightningd-1 2022-11-15T23:02:43.136Z DEBUG 022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: delayed_to_us_feerate = 7500, htlc_feerate = 11000, penalty_feerate = 7500 lightningd-1 2022-11-15T23:02:43.136Z DEBUG 022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Tracking output 664f4421f9f06d2d9e4c61850131466620ba76e55e2872940c0659a6b71b5a48:0: FUNDING_TRANSACTION/FUNDING_OUTPUT lightningd-1 2022-11-15T23:02:43.138Z DEBUG 022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Remote per-commit point: 024bb699a1ac413d11362a9dab8eaa6d61a2c0e3fab2d0fdfbbcac68bfffeb607e lightningd-1 2022-11-15T23:02:43.140Z DEBUG 022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Old remote per-commit point: 03da26778a010fd68b912a615a8cbbc45a0dcd950503489e63f6d64b6754c9e10a lightningd-1 2022-11-15T23:02:43.141Z DEBUG 022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: reducing max_possible_feerate from 11000... lightningd-1 2022-11-15T23:02:43.141Z DEBUG 022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: ... to 11000 lightningd-1 2022-11-15T23:02:43.141Z DEBUG 022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: commitnum = 6, revocations_received = 6 lightningd-1 2022-11-15T23:02:43.141Z INFO 022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-chan#1: State changed from FUNDING_SPEND_SEEN to ONCHAIN lightningd-1 2022-11-15T23:02:43.147Z DEBUG plugin-bcli: sendrawtx exit 27 (bitcoin-cli -regtest -datadir=/tmp/ltests-9ujwuqul/test_bookkeeping_closing_subsat_htlcs_1/lightning-1/ -rpcport=57247 -rpcuser=... -stdinrpcpass sendrawtransaction 02000000000101485a1bb7a659060c9472285ee576ba206646310185614c9e2d6df0f921444f6600000000009db0e28002a00f00000000000016001445503fa4b65ade3ffdb1a92057688456c9ffae1383130f0000000000220020be82765fdb17fd5568f2dd31c6cf1aabc620ef338995ec5d9a2f3e42f43ae487040047304402204bb3868bf3b521fd6bf39cabde740de0cf711f6251393dfa95dcf4e2edd294bd02207dd5fa24ca68821b2cb9985f5da1bf1613e9436788f19674bf8fbf7d268134af01473044022067ab1dd0c85fd465baea727a3c5db727f753e9f00c0f3f217274348074c6265c02202b4e2dd365ce01f7e00da585b2ecacda33fc07848acd487ab8a29660afa7e5ea0147522102324266de8403b3ab157a09f1f784d587af61831c998c151bcc21bb74c2b2314b2102e3bd38009866c9da8ec4aa99cc4ea9c6c0dd46df15c61ef0ce1f271291714e5752ae9c3ed620) error code: -27\nerror message:\nTransaction already in block chain lightningd-1 2022-11-15T23:02:43.147Z DEBUG plugin-bookkeeper: coin_move 2 (channel_close) 0msat -995999667msat chain_mvt 1668553363 lightningd-1 2022-11-15T23:02:43.148Z DEBUG 022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: billboard perm: Tracking our own unilateral close lightningd-1 2022-11-15T23:02:43.152Z DEBUG lightningd: Adding block 105: 3a5ffdbcfe8f5a6b774a45eaba6828176a70ff68af60639ed02ced494c617e25 lightningd-1 2022-11-15T23:02:43.155Z DEBUG 022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-hsmd: Got WIRE_HSMD_GET_PER_COMMITMENT_POINT lightningd-1 2022-11-15T23:02:43.155Z DEBUG 022d223620a359a47ff7f7ac447c85c46c923da53389221a0054c11c1e3ca31d59-onchaind-chan#1: Resolved FUNDING_TRANSACTION/FUNDING_OUTPUT by OUR_UNILATERAL (ad9c29733e6f8d0c43f25eb40378bdc2bc9d58a15586edef6c48999f4cf8c475) ```