---
# System prepended metadata

title: Debug bookkeeper plugin

---

# 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)
```