"Backup is out of date, we cannot continue safely. Emergency shutdown." after "lightning-cli stop" clean shutdown

[svewa]

I saw #326, but I can understand inconsistencies in backups during power fail situations, so I'm opening a new issue for this.

I shut down lightningd via lightning-cli stop and can't restart it with the same error. This happened quite a few time already, but this time I was on debug during the "stop" operation (info afterwards). Here is the slightly shortened log:

2022-02-21T17:01:02.236Z UNUSUAL lightningd: JSON-RPC shutdown
2022-02-21T17:01:02.236Z DEBUG   plugin-backup.py: Killing plugin: exited during normal operation
2022-02-21T17:01:02.236Z DEBUG   plugin-prometheus.py: Killing plugin: exited during normal operation
2022-02-21T17:01:02.236Z DEBUG   plugin-sparko_linux_amd64: Killing plugin: exited during normal operation
2022-02-21T17:01:02.238Z DEBUG   plugin-autoclean: Killing plugin: exited during normal operation
2022-02-21T17:01:02.238Z DEBUG   plugin-funder: Killing plugin: exited during normal operation
2022-02-21T17:01:02.238Z DEBUG   plugin-keysend: Killing plugin: exited during normal operation
2022-02-21T17:01:02.238Z DEBUG   plugin-offers: Killing plugin: exited during normal operation
2022-02-21T17:01:02.238Z DEBUG   plugin-pay: Killing plugin: exited during normal operation
2022-02-21T17:01:02.238Z DEBUG   plugin-txprepare: Killing plugin: exited during normal operation
2022-02-21T17:01:02.239Z DEBUG   plugin-bcli: Killing plugin: exited during normal operation
2022-02-21T17:01:02.239Z DEBUG   plugin-spenderp: Killing plugin: exited during normal operation
2022-02-21T17:01:02.239Z DEBUG   plugin-topology: Killing plugin: exited during normal operation
2022-02-21T17:01:02.239Z DEBUG   connectd: Shutting down
2022-02-21T17:01:02.240Z DEBUG   [...]-chan#21967: Failing HTLC 391 due to peer death
2022-02-21T17:01:02.240Z DEBUG   [...]-chan#22085: HTLC in 5862 RCVD_ADD_ACK_REVOCATION->SENT_REMOVE_HTLC
2022-02-21T17:01:02.240Z DEBUG   [...]-channeld-chan#15388: Status closed, but not exited. Killing
2022-02-21T17:01:02.240Z DEBUG   [...]-channeld-chan#21462: Status closed, but not exited. Killing
2022-02-21T17:01:02.288Z DEBUG   [...]-channeld-chan#22446: Status closed, but not exited. Killing
2022-02-21T17:01:02.289Z DEBUG   [...]-openingd-chan#22448: Status closed, but not exited. Killing
2022-02-21T17:01:02.289Z DEBUG   [...]-openingd-chan#22449: Status closed, but not exited. Killing
2022-02-21T17:01:02.289Z DEBUG   [...]-openingd-chan#22450: Status closed, but not exited. Killing
2022-02-21T17:01:02.289Z DEBUG   [...]-openingd-chan#22452: Status closed, but not exited. Killing
2022-02-21T17:01:02.289Z DEBUG   [...]-openingd-chan#22453: Status closed, but not exited. Killing
[~150 more of those]
2022-02-21T17:01:02.290Z DEBUG   gossipd: Shutting down
2022-02-21T17:01:03.019Z DEBUG   hsmd: Shutting down
2022-02-21T17:01:03.027Z DEBUG   lightningd: Command returned result after jcon close




2022-02-21T17:01:06.384Z INFO    plugin-backup.py: root        : Comparing backup version 3256048 versus first write version 3256050
2022-02-21T17:01:06.384Z INFO    plugin-backup.py: Comparing backup version 3256048 versus first write version 3256050
2022-02-21T17:01:06.384Z INFO    plugin-backup.py: Backup is out of date, we cannot continue safely. Emergency shutdown.

[laanwj]

I think this means c-lightning does another database commit after the plugin has been shut down. It challenges the backup plugin's assumption that it can listen in on any change. I would guess this is not fixable inside the plugin itself.