search

ElementsProject / lightning

Core Lightning — Lightning Network implementation focusing on spec compliance and performance
Other
2.83k stars 899 forks source link

plugin: dbbackup "Failed to write to backup: UNIQUE constraint failed: utxoset.txid, utxoset.outnum" #3007

Closed SimonVrouwe closed 5 years ago

SimonVrouwe commented 5 years ago

Was running version v0.7.2rc2-modded (no idea why it shows modded) together with the dbbackup.

edit: maybe plugin issues don't belong here, but maybe it is relevant

There was a chain reorg 26 aug, which triggered a write failure in the plugin when writing to backup:

2019-08-26T15:37:28.388Z DEBUG lightningd(18203): Adding block 591848: 0000000000000000001a190874bde466b6443be941e8add217eadce44bd4799f
2019-08-26T15:37:28.691Z **BROKEN** plugin-dbbackup.py Failed to write to backup: UNIQUE constraint failed: utxoset.txid, utxoset.outnum, SQL-statement: INSERT INTO utxoset ( txid, outnum, blockheight, spendheight, txindex, scriptpubkey, satoshis) VALUES(x'8695bd92b9d1230708afd3ab32a4e8a81c036d1f8b80b85da706f3377e0f5bc6', 1, 591848, NULL, 4, x'0020701a8d401c84fb13e6baf169d59684e17abd9fa216c8cc5b9fc63d622ff8c58d', 1129870000);

and crashed the node, see full crash log below. Looks similar to #1280, or maybe #2968?

What I found so far using sqlite3 .dbinfo on original db and backup:

The plugin runs on python3 (3.6.4 Anaconda Inc.) and its sqlite3 module shows indeed v3.22.0.

I forgot to make a copy of the original right after the crash, but I do have the backup, which correctly failed the compare-check when restarting the node.

2019-08-26T15:37:18.826Z DEBUG lightningd(18203): Removing stale block 591848: 000000000000000000181b1a2354620f66868a723c0c4d5b24e4be8bdfc35a7f
2019-08-26T15:37:25.536Z DEBUG lightningd(18203): Feerate estimate for urgent set to 8651 (was 9421)
2019-08-26T15:37:25.536Z DEBUG lightningd(18203): ... feerate estimate for slow hit floor 253
2019-08-26T15:37:25.548Z DEBUG lightningd(18203): lightning_channeld-03afa7a8196dbca763ee6f9a34b634a7adc03f154e5d6979fe654db5606b5fb2b1 chan #1371: We need 56263sat at feerate 8651 for 0 untrimmed htlcs: we have 3266865000msat/3266865000msat
2019-08-26T15:37:25.548Z DEBUG lightningd(18203): lightning_channeld-030c3f19d742ca294a55c00376b3b355c3c90d61c6b6b39554dbc7ac19b141c14f chan #1016: We need 168772sat at feerate 8651 for 0 untrimmed htlcs: we have 12250039532msat/12250039532msat
2019-08-26T15:37:25.548Z DEBUG lightningd(18203): lightning_channeld-0254ff808f53b2f8c45e74b70430f336c6c76ba2f4af289f48d6086ae6e60462d3 chan #1388: We need 90149sat at feerate 8651 for 0 untrimmed htlcs: we have 11844973000msat/11844973000msat
2019-08-26T15:37:25.548Z DEBUG lightningd(18203): lightning_channeld-03afa7a8196dbca763ee6f9a34b634a7adc03f154e5d6979fe654db5606b5fb2b1 chan #1371: Setting REMOTE feerate to 8651
2019-08-26T15:37:25.548Z DEBUG lightningd(18203): lightning_channeld-030c3f19d742ca294a55c00376b3b355c3c90d61c6b6b39554dbc7ac19b141c14f chan #1016: Setting REMOTE feerate to 8651
2019-08-26T15:37:25.548Z DEBUG lightningd(18203): lightning_channeld-0254ff808f53b2f8c45e74b70430f336c6c76ba2f4af289f48d6086ae6e60462d3 chan #1388: Setting REMOTE feerate to 8651
2019-08-26T15:37:25.548Z DEBUG lightningd(18203): lightning_channeld-03afa7a8196dbca763ee6f9a34b634a7adc03f154e5d6979fe654db5606b5fb2b1 chan #1371: peer_out WIRE_UPDATE_FEE
2019-08-26T15:37:25.549Z DEBUG lightningd(18203): lightning_channeld-030c3f19d742ca294a55c00376b3b355c3c90d61c6b6b39554dbc7ac19b141c14f chan #1016: peer_out WIRE_UPDATE_FEE
2019-08-26T15:37:25.549Z DEBUG lightningd(18203): lightning_channeld-0254ff808f53b2f8c45e74b70430f336c6c76ba2f4af289f48d6086ae6e60462d3 chan #1388: peer_out WIRE_UPDATE_FEE
2019-08-26T15:37:25.549Z DEBUG lightningd(18203): lightning_channeld-03afa7a8196dbca763ee6f9a34b634a7adc03f154e5d6979fe654db5606b5fb2b1 chan #1371: Trying commit
2019-08-26T15:37:25.549Z DEBUG lightningd(18203): lightning_channeld-030c3f19d742ca294a55c00376b3b355c3c90d61c6b6b39554dbc7ac19b141c14f chan #1016: Trying commit
2019-08-26T15:37:25.549Z DEBUG lightningd(18203): lightning_channeld-0254ff808f53b2f8c45e74b70430f336c6c76ba2f4af289f48d6086ae6e60462d3 chan #1388: Trying commit
2019-08-26T15:37:25.549Z DEBUG lightning_hsmd(18225): Client: Received message 19 from client
2019-08-26T15:37:25.550Z DEBUG lightningd(18203): lightning_channeld-030c3f19d742ca294a55c00376b3b355c3c90d61c6b6b39554dbc7ac19b141c14f chan #1016: Creating commit_sig signature 4966 304402201439864d987834d178eff509166e50a07c29ad88cffad87ace467953d898d5cb022057bccca34b1266db8af84211795387787839c9ac12d73fda74d645262743a91d01 for tx 02000000016c594b2d7917cad64ffcaaa9bbc506c11dc3edfb4c72db3625a108ee371cb184000000000014c9338002980c3d00000000002200208ae3b9e002b43b9e89f1f5c8ab3e27293a1d066a4f03ae7244e935f3c710a82c40d3ba000000000016001418a1359e10624d8f37f94f863d96f7626d396e64e03ab420 wscript 52210283899da2637295d8481f22d0d6827ab9ea18ee1e0ff74e85cf03cdb292489fbc2103f4afdf7931d2bb28281f6176d0e286354658139406af12e18d7a77b6bd9fbe0752ae key 03f4afdf7931d2bb28281f6176d0e286354658139406af12e18d7a77b6bd9fbe07
2019-08-26T15:37:25.550Z DEBUG lightningd(18203): lightning_channeld-03afa7a8196dbca763ee6f9a34b634a7adc03f154e5d6979fe654db5606b5fb2b1 chan #1371: Creating commit_sig signature 2195 3045022100879258ad67af918e6687224dd039398cd7fa355370596ea50ef52fa4745b435c02206277e178aa90df42f37c914adcfba5a46d5ce8c5cc121a447f4424ad2669890b01 for tx 0200000001f9448146e71c5e08e5279e2fb78b576123cabb4d22d5384da0cf271d9e9f55fa01000000001d6d4780020f721a0000000000220020bffc857f3597f3f6ca3994ed51b0862364a30ca0887f416b780d7121e8490e47bac031000000000016001441815cc035907e25e23bbd75dbef45bb2a9736c7f4300020 wscript 522102ba6fbab931d8c66f271976fa6b5bfa9eff28def08b5aa78deaf4c288ca0da9892103031ae93752885b1528c7cd5454a60e331c0b27b055063ecf0a5e30aad953552152ae key 03031ae93752885b1528c7cd5454a60e331c0b27b055063ecf0a5e30aad9535521
2019-08-26T15:37:25.550Z DEBUG lightning_hsmd(18225): Client: Received message 19 from client
2019-08-26T15:37:25.550Z DEBUG lightningd(18203): lightning_channeld-030c3f19d742ca294a55c00376b3b355c3c90d61c6b6b39554dbc7ac19b141c14f chan #1016: Telling master we're about to commit...
2019-08-26T15:37:25.551Z DEBUG lightningd(18203): lightning_channeld-03afa7a8196dbca763ee6f9a34b634a7adc03f154e5d6979fe654db5606b5fb2b1 chan #1371: Telling master we're about to commit...
2019-08-26T15:37:25.551Z DEBUG lightningd(18203): lightning_channeld-0254ff808f53b2f8c45e74b70430f336c6c76ba2f4af289f48d6086ae6e60462d3 chan #1388: Creating commit_sig signature 1541 304402205410b96be8b5fe75f4d17fee58ebc76e21f9881924ffd692c9c507af44df8612022001fe9fd958d9296284a00e915b539f7fd71a5a3bb7c1c551c23781a31db752d101 for tx 02000000019e4c7c148e322fc0d0fbb4291689975a55759b7bf336b2e19c99e8151802bba10100000000336ebf800292424b000000000022002056116b49915c753d50b91221f0c478477b17a7bb78fb3646b0eafa4b271200bef6a4b400000000001600143cfac6a72f5b53066f3437e3dafd4ebb73d6be1c769ab820 wscript 5221036fc22a4d50445ab6b8cc7aacd22a949c241472d81046b93f28e258a009e0bd3b2103b56a364dd8dd9032a280f2e19aa14f138cf7788f903ce722ce126118eb18186852ae key 036fc22a4d50445ab6b8cc7aacd22a949c241472d81046b93f28e258a009e0bd3b
2019-08-26T15:37:25.551Z DEBUG lightning_hsmd(18225): Client: Received message 19 from client
2019-08-26T15:37:25.551Z DEBUG lightningd(18203): lightning_channeld-030c3f19d742ca294a55c00376b3b355c3c90d61c6b6b39554dbc7ac19b141c14f chan #1016: Sending master 1020
2019-08-26T15:37:25.551Z DEBUG lightningd(18203): lightning_channeld-03afa7a8196dbca763ee6f9a34b634a7adc03f154e5d6979fe654db5606b5fb2b1 chan #1371: Sending master 1020
2019-08-26T15:37:25.551Z DEBUG lightningd(18203): lightning_channeld-0254ff808f53b2f8c45e74b70430f336c6c76ba2f4af289f48d6086ae6e60462d3 chan #1388: Telling master we're about to commit...
2019-08-26T15:37:26.468Z DEBUG lightning_hsmd(18225): Client: Received message 19 from client
2019-08-26T15:37:26.468Z DEBUG lightningd(18203): lightning_channeld-03afa7a8196dbca763ee6f9a34b634a7adc03f154e5d6979fe654db5606b5fb2b1 chan #1371: ... , awaiting 1120
2019-08-26T15:37:26.468Z DEBUG lightningd(18203): lightning_channeld-030c3f19d742ca294a55c00376b3b355c3c90d61c6b6b39554dbc7ac19b141c14f chan #1016: ... , awaiting 1120
2019-08-26T15:37:26.468Z DEBUG lightningd(18203): lightning_channeld-03efccf2c383d7bf340da9a3f02e2c23104a0e4fe8ac1a880c8e2dc92fbdacd9df chan #1383: We need 56261sat at feerate 8651 for 0 untrimmed htlcs: we have 4556425485msat/4556425485msat
2019-08-26T15:37:26.468Z DEBUG lightningd(18203): lightning_channeld-0254ff808f53b2f8c45e74b70430f336c6c76ba2f4af289f48d6086ae6e60462d3 chan #1388: Sending master 1020
2019-08-26T15:37:26.469Z DEBUG lightningd(18203): lightning_channeld-03afa7a8196dbca763ee6f9a34b634a7adc03f154e5d6979fe654db5606b5fb2b1 chan #1371: Got it!
2019-08-26T15:37:26.469Z DEBUG lightningd(18203): lightning_channeld-030c3f19d742ca294a55c00376b3b355c3c90d61c6b6b39554dbc7ac19b141c14f chan #1016: Got it!
2019-08-26T15:37:26.469Z DEBUG lightningd(18203): lightning_channeld-03efccf2c383d7bf340da9a3f02e2c23104a0e4fe8ac1a880c8e2dc92fbdacd9df chan #1383: Setting REMOTE feerate to 8651
2019-08-26T15:37:26.923Z DEBUG lightningd(18203): lightning_channeld-03afa7a8196dbca763ee6f9a34b634a7adc03f154e5d6979fe654db5606b5fb2b1 chan #1371: Sending commit_sig with 0 htlc sigs
2019-08-26T15:37:26.923Z DEBUG lightningd(18203): lightning_channeld-030c3f19d742ca294a55c00376b3b355c3c90d61c6b6b39554dbc7ac19b141c14f chan #1016: Sending commit_sig with 0 htlc sigs
2019-08-26T15:37:26.923Z DEBUG lightningd(18203): lightning_channeld-03efccf2c383d7bf340da9a3f02e2c23104a0e4fe8ac1a880c8e2dc92fbdacd9df chan #1383: peer_out WIRE_UPDATE_FEE
2019-08-26T15:37:26.923Z DEBUG lightningd(18203): lightning_channeld-0254ff808f53b2f8c45e74b70430f336c6c76ba2f4af289f48d6086ae6e60462d3 chan #1388: ... , awaiting 1120
2019-08-26T15:37:26.923Z DEBUG lightningd(18203): lightning_channeld-03afa7a8196dbca763ee6f9a34b634a7adc03f154e5d6979fe654db5606b5fb2b1 chan #1371: peer_out WIRE_COMMITMENT_SIGNED
2019-08-26T15:37:26.923Z DEBUG lightningd(18203): lightning_channeld-030c3f19d742ca294a55c00376b3b355c3c90d61c6b6b39554dbc7ac19b141c14f chan #1016: peer_out WIRE_COMMITMENT_SIGNED
2019-08-26T15:37:26.924Z DEBUG lightningd(18203): lightning_channeld-03efccf2c383d7bf340da9a3f02e2c23104a0e4fe8ac1a880c8e2dc92fbdacd9df chan #1383: Trying commit
2019-08-26T15:37:26.924Z DEBUG lightningd(18203): lightning_channeld-0254ff808f53b2f8c45e74b70430f336c6c76ba2f4af289f48d6086ae6e60462d3 chan #1388: Got it!
2019-08-26T15:37:26.924Z DEBUG lightningd(18203): lightning_channeld-03afa7a8196dbca763ee6f9a34b634a7adc03f154e5d6979fe654db5606b5fb2b1 chan #1371: peer_in WIRE_REVOKE_AND_ACK
2019-08-26T15:37:26.924Z DEBUG lightningd(18203): lightning_channeld-03efccf2c383d7bf340da9a3f02e2c23104a0e4fe8ac1a880c8e2dc92fbdacd9df chan #1383: Creating commit_sig signature 2293 3045022100b1c288884259d450d79579058af6921680e92440a25b453d2b1b0f3af97d63a302200dacbfc3767510649a4facb61c7c5c2855ee7ae240a30eabbf99b0ab720f7a5a01 for tx 020000000109529d310b10628f1d9a6d1a5a731ca85df65026959b66b8c4b00b42e3c510080000000000449228800290c3060000000000220020aa5b5d231674fa886c145fa3aee65f472c38b90bc105c0f5fb91f094299e7ff6126e450000000000160014793ec106ba56b772ae48c0481fdfdb75b61ae9598ef5c520 wscript 522102690a08f79f78a092c34b47855bafe94474e2a00a7fdc9704736e945383f348982103a19e4fb0d7ae764a66f2423ccca2ad2f01e9dcca977123dbe0b89419b9c14a0352ae key 03a19e4fb0d7ae764a66f2423ccca2ad2f01e9dcca977123dbe0b89419b9c14a03
2019-08-26T15:37:26.924Z DEBUG lightningd(18203): lightning_channeld-0254ff808f53b2f8c45e74b70430f336c6c76ba2f4af289f48d6086ae6e60462d3 chan #1388: Sending commit_sig with 0 htlc sigs
2019-08-26T15:37:26.924Z DEBUG lightningd(18203): lightning_channeld-03afa7a8196dbca763ee6f9a34b634a7adc03f154e5d6979fe654db5606b5fb2b1 chan #1371: Received revoke_and_ack
2019-08-26T15:37:26.924Z DEBUG lightningd(18203): lightning_channeld-03efccf2c383d7bf340da9a3f02e2c23104a0e4fe8ac1a880c8e2dc92fbdacd9df chan #1383: Telling master we're about to commit...
2019-08-26T15:37:26.924Z DEBUG lightningd(18203): lightning_channeld-0254ff808f53b2f8c45e74b70430f336c6c76ba2f4af289f48d6086ae6e60462d3 chan #1388: peer_out WIRE_COMMITMENT_SIGNED
2019-08-26T15:37:26.924Z DEBUG lightningd(18203): lightning_channeld-03afa7a8196dbca763ee6f9a34b634a7adc03f154e5d6979fe654db5606b5fb2b1 chan #1371: Applying feerate 8651 to LOCAL
2019-08-26T15:37:26.924Z DEBUG lightningd(18203): lightning_channeld-03efccf2c383d7bf340da9a3f02e2c23104a0e4fe8ac1a880c8e2dc92fbdacd9df chan #1383: Sending master 1020
2019-08-26T15:37:26.925Z DEBUG lightningd(18203): lightning_channeld-03afa7a8196dbca763ee6f9a34b634a7adc03f154e5d6979fe654db5606b5fb2b1 chan #1371: Commits outstanding after recv revoke_and_ack
2019-08-26T15:37:27.613Z DEBUG lightningd(18203): lightning_channeld-03afa7a8196dbca763ee6f9a34b634a7adc03f154e5d6979fe654db5606b5fb2b1 chan #1371: Sending master 1022
2019-08-26T15:37:27.613Z DEBUG lightningd(18203): lightning_channeld-03efccf2c383d7bf340da9a3f02e2c23104a0e4fe8ac1a880c8e2dc92fbdacd9df chan #1383: ... , awaiting 1120
2019-08-26T15:37:27.613Z DEBUG lightningd(18203): lightning_channeld-0254ff808f53b2f8c45e74b70430f336c6c76ba2f4af289f48d6086ae6e60462d3 chan #1388: peer_in WIRE_REVOKE_AND_ACK
2019-08-26T15:37:27.614Z DEBUG lightningd(18203): 03afa7a8196dbca763ee6f9a34b634a7adc03f154e5d6979fe654db5606b5fb2b1 chan #1371: got revoke 2194: 0 changed
2019-08-26T15:37:28.334Z DEBUG lightningd(18203): lightning_channeld-03efccf2c383d7bf340da9a3f02e2c23104a0e4fe8ac1a880c8e2dc92fbdacd9df chan #1383: Got it!
2019-08-26T15:37:28.334Z DEBUG lightningd(18203): lightning_channeld-0254ff808f53b2f8c45e74b70430f336c6c76ba2f4af289f48d6086ae6e60462d3 chan #1388: Received revoke_and_ack
2019-08-26T15:37:28.334Z DEBUG lightningd(18203): lightning_channeld-03afa7a8196dbca763ee6f9a34b634a7adc03f154e5d6979fe654db5606b5fb2b1 chan #1371: ... , awaiting 1122
2019-08-26T15:37:28.388Z DEBUG lightningd(18203): Adding block 591848: 0000000000000000001a190874bde466b6443be941e8add217eadce44bd4799f
2019-08-26T15:37:28.691Z **BROKEN** plugin-dbbackup.py Failed to write to backup: UNIQUE constraint failed: utxoset.txid, utxoset.outnum, SQL-statement: INSERT INTO utxoset ( txid, outnum, blockheight, spendheight, txindex, scriptpubkey, satoshis) VALUES(x'8695bd92b9d1230708afd3ab32a4e8a81c036d1f8b80b85da706f3377e0f5bc6', 1, 591848, NULL, 4, x'0020701a8d401c84fb13e6baf169d59684e17abd9fa216c8cc5b9fc63d622ff8c58d', 1129870000);
Plugin returned failed db_write: 

{"jsonrpc": "2.0", "id": 8146, "result": false}

.
2019-08-26T15:37:28.753Z **BROKEN** lightningd(18203): Plugin returned failed db_write: ??{"jsonrpc": "2.0", "id": 8146, "result": false}??.
lightningd: FATAL SIGNAL 6 (version v0.7.2rc2-modded)
0x561906e01ead send_backtrace
        common/daemon.c:40
0x561906e01f53 crashdump
        common/daemon.c:53
0x7fcf7b24205f ???
        ???:0
0x7fcf7b241fff ???
        ???:0
0x7fcf7b243429 ???
        ???:0
0x561906ddad42 fatal
        lightningd/log.c:639
0x561906df9494 db_hook_response
        lightningd/plugin_hook.c:148
0x561906df60f8 plugin_response_handle
        lightningd/plugin.c:251
0x561906df627d plugin_read_json_one
        lightningd/plugin.c:341
0x561906df63aa plugin_read_json
        lightningd/plugin.c:366
0x561906e49cd0 next_plan
        ccan/ccan/io/io.c:59
0x561906e4a84d do_plan
        ccan/ccan/io/io.c:407
0x561906e4a88b io_ready
        ccan/ccan/io/io.c:417
0x561906e4c8da io_loop
        ccan/ccan/io/poll.c:445
0x561906df8930 plugin_exclusive_loop
        lightningd/plugin.c:1136
0x561906df9611 plugin_hook_db_sync
        lightningd/plugin_hook.c:185
0x561906e30371 db_report_changes
        wallet/db.c:624
0x561906e304c6 db_commit_transaction
        wallet/db.c:654
0x561906dc0651 bcli_finished
        lightningd/bitcoind.c:228
0x561906e4c1c6 destroy_conn
        ccan/ccan/io/poll.c:244
0x561906e4c1e6 destroy_conn_close_fd
        ccan/ccan/io/poll.c:250
0x561906e59e57 notify
        ccan/ccan/tal/tal.c:235
0x561906e5a346 del_tree
        ccan/ccan/tal/tal.c:397
0x561906e5a6d2 tal_free
        ccan/ccan/tal/tal.c:481
0x561906e4a9eb io_close
        ccan/ccan/io/io.c:450
0x561906e4c901 io_loop
        ccan/ccan/io/poll.c:449
0x561906dd26e9 io_loop_with_timers
        lightningd/io_loop_with_timers.c:24
0x561906dd8b40 main
        lightningd/lightningd.c:834
0x7fcf7b22f2e0 ???
        ???:0
0x561906dbf619 ???
        ???:0
0xffffffffffffffff ???
        ???:0
2019-08-26T15:37:28.997Z **BROKEN** lightningd(18203): FATAL SIGNAL 6 (version v0.7.2rc2-modded)
2019-08-26T15:37:28.997Z **BROKEN** lightningd(18203): backtrace: common/daemon.c:45 (send_backtrace) 0x561906e01f03
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: common/daemon.c:53 (crashdump) 0x561906e01f53
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: (null):0 ((null)) 0x7fcf7b24205f
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: (null):0 ((null)) 0x7fcf7b241fff
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: (null):0 ((null)) 0x7fcf7b243429
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: lightningd/log.c:639 (fatal) 0x561906ddad42
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: lightningd/plugin_hook.c:148 (db_hook_response) 0x561906df9494
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: lightningd/plugin.c:251 (plugin_response_handle) 0x561906df60f8
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: lightningd/plugin.c:341 (plugin_read_json_one) 0x561906df627d
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: lightningd/plugin.c:366 (plugin_read_json) 0x561906df63aa
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: ccan/ccan/io/io.c:59 (next_plan) 0x561906e49cd0
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: ccan/ccan/io/io.c:407 (do_plan) 0x561906e4a84d
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: ccan/ccan/io/io.c:417 (io_ready) 0x561906e4a88b
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: ccan/ccan/io/poll.c:445 (io_loop) 0x561906e4c8da
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: lightningd/plugin.c:1136 (plugin_exclusive_loop) 0x561906df8930
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: lightningd/plugin_hook.c:185 (plugin_hook_db_sync) 0x561906df9611
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: wallet/db.c:624 (db_report_changes) 0x561906e30371
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: wallet/db.c:654 (db_commit_transaction) 0x561906e304c6
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: lightningd/bitcoind.c:228 (bcli_finished) 0x561906dc0651
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: ccan/ccan/io/poll.c:244 (destroy_conn) 0x561906e4c1c6
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: ccan/ccan/io/poll.c:250 (destroy_conn_close_fd) 0x561906e4c1e6
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: ccan/ccan/tal/tal.c:235 (notify) 0x561906e59e57
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: ccan/ccan/tal/tal.c:397 (del_tree) 0x561906e5a346
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: ccan/ccan/tal/tal.c:481 (tal_free) 0x561906e5a6d2
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: ccan/ccan/io/io.c:450 (io_close) 0x561906e4a9eb
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: ccan/ccan/io/poll.c:449 (io_loop) 0x561906e4c901
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: lightningd/io_loop_with_timers.c:24 (io_loop_with_timers) 0x561906dd26e9
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: lightningd/lightningd.c:834 (main) 0x561906dd8b40
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: (null):0 ((null)) 0x7fcf7b22f2e0
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: (null):0 ((null)) 0x561906dbf619
2019-08-26T15:37:28.998Z **BROKEN** lightningd(18203): backtrace: (null):0 ((null)) 0xffffffffffffffff
Log dumped in crash.log.20190826153728
lightning_channeld: Could not set sync read from master: Connection reset by peer (version v0.7.2rc2-modded)
lightning_channeld: Could not set sync read from master: Connection reset by peer (version v0.7.2rc2-modded)
lightning_channeld: Could not set sync read from master: Connection reset by peer (version v0.7.2rc2-modded)
0x55b396232e52 send_backtrace
        common/daemon.c:40
0x55b39623ec5b status_failed
        common/status.c:192
0x55b39621f8ec master_wait_sync_reply
        channeld/channeld.c:804
0x55b3962223d2 handle_peer_revoke_and_ack
        channeld/channeld.c:1581
0x55b396222db7 peer_in
        channeld/channeld.c:1840
0x55b396226283 main
        channeld/channeld.c:3138
0x7f47b50dc2e0 ???
        ???:0
0x55b39621d779 ???
        ???:0
0xffffffffffffffff ???
        ???:0
0x5627f1db0e52 send_backtrace
        common/daemon.c:40
0x5627f1dbcc5b status_failed
        common/status.c:192
0x5627f1d9d8ec master_wait_sync_reply
        channeld/channeld.c:804
0x5627f1da03d2 handle_peer_revoke_and_ack
        channeld/channeld.c:1581
0x5627f1da0db7 peer_in
        channeld/channeld.c:1840
0x5627f1da4283 main
        channeld/channeld.c:3138
0x7f2d701da2e0 ???
        ???:0
0x5627f1d9b779 ???
        ???:0
0xffffffffffffffff ???
        ???:0
0x56040c590e52 send_backtrace
        common/daemon.c:40
0x56040c59cc5b status_failed
        common/status.c:192
0x56040c57d8ec master_wait_sync_reply
        channeld/channeld.c:804
0x56040c57fe98 handle_peer_commit_sig
        channeld/channeld.c:1492
0x56040c580d87 peer_in
        channeld/channeld.c:1834
0x56040c584283 main
        channeld/channeld.c:3138
0x7ff5ea25f2e0 ???
        ???:0
0x56040c57b779 ???
        ???:0
0xffffffffffffffff ???
        ???:0
cdecker commented 5 years ago

I've seen this before when the DB is not initialized correctly after opening it: you need to execute the following statement to enable foreign keys:

 PRAGMA foreign_keys = ON;

This is needed since we rely on foreign key relationships to cascade deletions from one table to dependent ones. In this specific case it is likely that the blocks entry for block 591848 was deleted, but did not result in the deletion cascading the deletion to the entries in utxoset which would have avoided the conflict. I'm pretty sure that other constraints will also have been violated so please grab a new copy of the DB instead of trying to recover.

cdecker commented 5 years ago

I added some comments to this end on the dbbackup PR here https://github.com/lightningd/plugins/pull/40.

I think that plugin is still under development and the issues should be reported there, so closing this :wink:

SimonVrouwe commented 5 years ago

you need to execute the following statement to enable foreign keys:

 PRAGMA foreign_keys = ON;

How could the backup have missed that one? It should have nicely been reported to the plugin https://github.com/ElementsProject/lightning/blob/3ef5160fa7cc8eadb9dc9cf5443e02ebec79ed8e/wallet/db.c#L673-L674

cdecker commented 5 years ago

Might be an issue with the way the plugin buffers statements before it is inited?

SimonVrouwe commented 5 years ago

Found it, creating the initial backup from a copy of the original does not copy the PRAGMA ! I guess a PRAGMA is more a property of the connection.

@cdecker Thanks for the push in the right direction.