Merge #1376: Get timestamp of last completed poll of the blockchain

dee9554c518793b57b71965d835905300ef86fbc database: add `wallet()` method and use in `getinfo` command (Michael Mallan)
4694eaaef9f6650047ab5a527c8c7852a01ab7fe poller: don't poll now if blockchain syncing (Michael Mallan)
0f9f1f352c9bef22d7b21508d47daa77573b446c commands: return last poll timestamp from `getinfo` (Michael Mallan)
c6add0aeb1a0d16301a96745b560b94b31476d13 qa: add method to get lianad poll interval (Michael Mallan)
61e39f7d8623c288639122e295c26a0961687cb9 poller: store last poll timestamp (Michael Mallan)
e9fdcde995a57695769637228e503779c84a1aed database: get and set last poll timestamp (Michael Mallan)
a2b79f1b07bca86e955603ecb2f2489686ae901d sqlite: get and set last poll timestamp (Michael Mallan)

Pull request description:

  This is a first step towards #1373.

  The timestamp of the last completed poll of the blockchain will be stored in the database, and this value will be made available via the `getinfo` command.

ACKs for top commit:
  edouardparis:
    ACK dee9554c518793b57b71965d835905300ef86fbc

Tree-SHA512: 32706d516e9915d7320583b37990a5d907bb254905efbb0318c5eae4b27753800933d1b9e68bf43a0190c27d8a5d349f633c0e6e70ba21815ed6eed1648f0625

doc/API.md

@@ -53,15 +53,16 @@ This command does not take any parameter for now.
 
 #### Response
 
-| Field                | Type          | Description                                                                                  |
-| -------------------- | ------------- | -------------------------------------------------------------------------------------------- |
-| `version`            | string        | Version following the [SimVer](http://www.simver.org/) format                                |
-| `network`            | string        | Answer can be `mainnet`, `testnet`, `regtest`                                                |
-| `block_height`       | integer       | The block height we are synced at.                                                           |
-| `sync`               | float         | The synchronization progress as percentage (`0 < sync < 1`)                                  |
-| `descriptors`        | object        | Object with the name of the descriptor as key and the descriptor string as value             |
-| `rescan_progress`    | float or null | Progress of an ongoing rescan as a percentage (between 0 and 1) if there is any              |
-| `timestamp`          | integer       | Unix timestamp of wallet creation date                                                       |
+| Field                | Type            | Description                                                                                  |
+| -------------------- | --------------- | -------------------------------------------------------------------------------------------- |
+| `version`            | string          | Version following the [SimVer](http://www.simver.org/) format                                |
+| `network`            | string          | Answer can be `mainnet`, `testnet`, `regtest`                                                |
+| `block_height`       | integer         | The block height we are synced at.                                                           |
+| `sync`               | float           | The synchronization progress as percentage (`0 < sync < 1`)                                  |
+| `descriptors`        | object          | Object with the name of the descriptor as key and the descriptor string as value             |
+| `rescan_progress`    | float or null   | Progress of an ongoing rescan as a percentage (between 0 and 1) if there is any              |
+| `timestamp`          | integer         | Unix timestamp of wallet creation date                                                       |
+| `last_poll_timestamp`| integer or null | Unix timestamp of last poll (if any) of the blockchain                                       |
 
 ### `getnewaddress`
 

src/bitcoin/poller/looper.rs

@@ -4,7 +4,7 @@ use crate::{
     descriptors,
 };
 
-use std::{collections::HashSet, sync, thread, time};
+use std::{collections::HashSet, convert::TryInto, sync, thread, time};
 
 use miniscript::bitcoin::{self, secp256k1};
 
@@ -401,4 +401,11 @@ pub fn poll(
     let mut db_conn = db.connection();
     updates(&mut db_conn, bit, descs, secp);
     rescan_check(&mut db_conn, bit, descs, secp);
+    let now: u32 = time::SystemTime::now()
+        .duration_since(time::UNIX_EPOCH)
+        .expect("current system time must be later than epoch")
+        .as_secs()
+        .try_into()
+        .expect("system clock year is earlier than 2106");
+    db_conn.set_last_poll(now);
 }

src/bitcoin/poller/mod.rs

@@ -89,9 +89,28 @@ impl Poller {
                 }
                 Ok(PollerMessage::PollNow(sender)) => {
                     // We've been asked to poll, don't wait any further and signal completion to
-                    // the caller.
+                    // the caller, unless the block chain is still syncing.
+                    // Polling while the block chain is syncing could lead to poller restarts
+                    // if the height increases before completion, and in any case this is consistent
+                    // with regular poller behaviour.
+                    if !synced {
+                        let progress = self.bit.sync_progress();
+                        log::info!(
+                            "Block chain synchronization progress: {:.2}% ({} blocks / {} headers)",
+                            progress.rounded_up_progress() * 100.0,
+                            progress.blocks,
+                            progress.headers
+                        );
+                        synced = progress.is_complete();
+                    }
+                    // Update `last_poll` even if we don't poll now so that we don't attempt another
+                    // poll too soon.
                     last_poll = Some(time::Instant::now());
-                    looper::poll(&mut self.bit, &self.db, &self.secp, &self.descs);
+                    if synced {
+                        looper::poll(&mut self.bit, &self.db, &self.secp, &self.descs);
+                    } else {
+                        log::warn!("Skipped poll as block chain is still synchronizing.");
+                    }
                     if let Err(e) = sender.send(()) {
                         log::error!("Error sending immediate poll completion signal: {}.", e);
                     }

src/commands/mod.rs

@@ -309,10 +309,10 @@ impl DaemonControl {
     /// Get information about the current state of the daemon
     pub fn get_info(&self) -> GetInfoResult {
         let mut db_conn = self.db.connection();
-
         let block_height = db_conn.chain_tip().map(|tip| tip.height).unwrap_or(0);
-        let rescan_progress = db_conn
-            .rescan_timestamp()
+        let wallet = db_conn.wallet();
+        let rescan_progress = wallet
+            .rescan_timestamp
             .map(|_| self.bitcoin.rescan_progress().unwrap_or(1.0));
         GetInfoResult {
             version: VERSION.to_string(),
@@ -323,7 +323,8 @@ impl DaemonControl {
                 main: self.config.main_descriptor.clone(),
             },
             rescan_progress,
-            timestamp: db_conn.timestamp(),
+            timestamp: wallet.timestamp,
+            last_poll_timestamp: wallet.last_poll_timestamp,
         }
     }
 
@@ -1127,6 +1128,8 @@ pub struct GetInfoResult {
     pub rescan_progress: Option<f64>,
     /// Timestamp at wallet creation date
     pub timestamp: u32,
+    /// Timestamp of last poll, if any.
+    pub last_poll_timestamp: Option<u32>,
 }
 
 #[derive(Debug, Clone, Serialize, Deserialize)]

src/database/mod.rs

@@ -22,6 +22,23 @@ use std::{
 
 use miniscript::bitcoin::{self, bip32, psbt::Psbt, secp256k1};
 
+/// Information about the wallet.
+///
+/// All timestamps are the number of seconds since the UNIX epoch.
+#[derive(Clone, Debug)]
+pub struct Wallet {
+    /// Timestamp at wallet creation time.
+    pub timestamp: u32,
+    /// Derivation index for the next receiving address.
+    pub receive_index: bip32::ChildNumber,
+    /// Derivation index for the next change address.
+    pub change_index: bip32::ChildNumber,
+    /// Timestamp to start rescanning from, if any.
+    pub rescan_timestamp: Option<u32>,
+    /// Timestamp at which the last poll of the blockchain completed, if any,
+    pub last_poll_timestamp: Option<u32>,
+}
+
 pub trait DatabaseInterface: Send {
     fn connection(&self) -> Box<dyn DatabaseConnection>;
 }
@@ -46,6 +63,9 @@ pub trait DatabaseConnection {
     /// The network we are operating on.
     fn network(&mut self) -> bitcoin::Network;
 
+    /// Get the `Wallet`.
+    fn wallet(&mut self) -> Wallet;
+
     /// The timestamp at wallet creation time
     fn timestamp(&mut self) -> u32;
 
@@ -81,6 +101,14 @@ pub trait DatabaseConnection {
     /// Mark the rescan as complete.
     fn complete_rescan(&mut self);
 
+    /// Get the timestamp at which the last poll of the blockchain completed, if any,
+    /// as the number of seconds since the UNIX epoch.
+    fn last_poll_timestamp(&mut self) -> Option<u32>;
+
+    /// Set the timestamp at which the last poll of the blockchain completed,
+    /// where `timestamp` should be given as the number of seconds since the UNIX epoch.
+    fn set_last_poll(&mut self, timestamp: u32);
+
     /// Get the derivation index for this address, as well as whether this address is change.
     fn derivation_index_by_address(
         &mut self,
@@ -176,8 +204,19 @@ impl DatabaseConnection for SqliteConn {
         self.db_tip().network
     }
 
+    fn wallet(&mut self) -> Wallet {
+        let db_wallet = self.db_wallet();
+        Wallet {
+            timestamp: db_wallet.timestamp,
+            receive_index: db_wallet.deposit_derivation_index,
+            change_index: db_wallet.change_derivation_index,
+            rescan_timestamp: db_wallet.rescan_timestamp,
+            last_poll_timestamp: db_wallet.last_poll_timestamp,
+        }
+    }
+
     fn timestamp(&mut self) -> u32 {
-        self.db_wallet().timestamp
+        self.wallet().timestamp
     }
 
     fn update_tip(&mut self, tip: &BlockChainTip) {
@@ -185,7 +224,7 @@ impl DatabaseConnection for SqliteConn {
     }
 
     fn receive_index(&mut self) -> bip32::ChildNumber {
-        self.db_wallet().deposit_derivation_index
+        self.wallet().receive_index
     }
 
     fn set_receive_index(
@@ -197,7 +236,7 @@ impl DatabaseConnection for SqliteConn {
     }
 
     fn change_index(&mut self) -> bip32::ChildNumber {
-        self.db_wallet().change_derivation_index
+        self.wallet().change_index
     }
 
     fn set_change_index(
@@ -209,7 +248,7 @@ impl DatabaseConnection for SqliteConn {
     }
 
     fn rescan_timestamp(&mut self) -> Option<u32> {
-        self.db_wallet().rescan_timestamp
+        self.wallet().rescan_timestamp
     }
 
     fn set_rescan(&mut self, timestamp: u32) {
@@ -220,6 +259,15 @@ impl DatabaseConnection for SqliteConn {
         self.complete_wallet_rescan()
     }
 
+    fn last_poll_timestamp(&mut self) -> Option<u32> {
+        self.wallet().last_poll_timestamp
+    }
+
+    fn set_last_poll(&mut self, timestamp: u32) {
+        self.set_wallet_last_poll_timestamp(timestamp)
+            .expect("database must be available")
+    }
+
     fn coins(
         &mut self,
         statuses: &[CoinStatus],

src/database/sqlite/mod.rs

@@ -43,7 +43,7 @@ use miniscript::bitcoin::{
     secp256k1,
 };
 
-const DB_VERSION: i64 = 5;
+const DB_VERSION: i64 = 6;
 
 /// Last database version for which Bitcoin transactions were not stored in database. In practice
 /// this meant we relied on the bitcoind watchonly wallet to store them for us.
@@ -371,6 +371,20 @@ impl SqliteConn {
         .expect("Database must be available");
     }
 
+    // Sqlite supports i64 integers so we use u32 for the timestamp.
+    /// Set the last poll timestamp, where `timestamp` is seconds since UNIX epoch.
+    pub fn set_wallet_last_poll_timestamp(&mut self, timestamp: u32) -> Result<(), SqliteDbError> {
+        db_exec(&mut self.conn, |db_tx| {
+            db_tx
+                .execute(
+                    "UPDATE wallets SET last_poll_timestamp = (?1) WHERE id = (?2)",
+                    rusqlite::params![timestamp, WALLET_ID],
+                )
+                .map(|_| ())
+        })
+        .map_err(SqliteDbError::Rusqlite)
+    }
+
     /// Get all the coins from DB, optionally filtered by coin status and/or outpoint.
     pub fn coins(
         &mut self,
@@ -2384,7 +2398,7 @@ CREATE TABLE labels (
     }
 
     #[test]
-    fn v0_to_v5_migration() {
+    fn v0_to_v6_migration() {
         let secp = secp256k1::Secp256k1::verification_only();
 
         // Create a database with version 0, using the old schema.
@@ -2490,7 +2504,7 @@ CREATE TABLE labels (
         {
             let mut conn = db.connection().unwrap();
             let version = conn.db_version();
-            assert_eq!(version, 5);
+            assert_eq!(version, 6);
         }
         // We should now be able to insert another PSBT, to query both, and the first PSBT must
         // have no associated timestamp.
@@ -2552,11 +2566,19 @@ CREATE TABLE labels (
             assert_eq!(db_labels[0].value, "hello");
         }
 
+        // In v6, we can get and set the last poll timestamp.
+        {
+            let mut conn = db.connection().unwrap();
+            assert!(conn.db_wallet().last_poll_timestamp.is_none());
+            conn.set_wallet_last_poll_timestamp(1234567).unwrap();
+            assert_eq!(conn.db_wallet().last_poll_timestamp, Some(1234567));
+        }
+
         fs::remove_dir_all(tmp_dir).unwrap();
     }
 
     #[test]
-    fn v3_to_v5_migration() {
+    fn v3_to_v6_migration() {
         let secp = secp256k1::Secp256k1::verification_only();
 
         // Create a database with version 3, using the old schema.
@@ -2718,10 +2740,10 @@ CREATE TABLE labels (
 
             // Migrate the DB.
             maybe_apply_migration(&db_path, &bitcoin_txs).unwrap();
-            assert_eq!(conn.db_version(), 5);
+            assert_eq!(conn.db_version(), 6);
             // Migrating twice will be a no-op. No need to pass `bitcoin_txs` second time.
             maybe_apply_migration(&db_path, &[]).unwrap();
-            assert!(conn.db_version() == 5);
+            assert!(conn.db_version() == 6);
             let coins_post = conn.coins(&[], &[]);
             assert_eq!(coins_pre, coins_post);
         }

src/database/sqlite/schema.rs

@@ -30,7 +30,8 @@ CREATE TABLE wallets (
     main_descriptor TEXT NOT NULL,
     deposit_derivation_index INTEGER NOT NULL,
     change_derivation_index INTEGER NOT NULL,
-    rescan_timestamp INTEGER
+    rescan_timestamp INTEGER,
+    last_poll_timestamp INTEGER
 );
 
 /* Our (U)TxOs.
@@ -140,6 +141,7 @@ pub struct DbWallet {
     pub deposit_derivation_index: bip32::ChildNumber,
     pub change_derivation_index: bip32::ChildNumber,
     pub rescan_timestamp: Option<u32>,
+    pub last_poll_timestamp: Option<u32>,
 }
 
 impl TryFrom<&rusqlite::Row<'_>> for DbWallet {
@@ -159,6 +161,7 @@ impl TryFrom<&rusqlite::Row<'_>> for DbWallet {
         let change_derivation_index = bip32::ChildNumber::from(der_idx);
 
         let rescan_timestamp = row.get(5)?;
+        let last_poll_timestamp = row.get(6)?;
 
         Ok(DbWallet {
             id,
@@ -167,6 +170,7 @@ impl TryFrom<&rusqlite::Row<'_>> for DbWallet {
             deposit_derivation_index,
             change_derivation_index,
             rescan_timestamp,
+            last_poll_timestamp,
         })
     }
 }

src/database/sqlite/utils.rs

@@ -294,6 +294,19 @@ fn migrate_v4_to_v5(
     Ok(())
 }
 
+fn migrate_v5_to_v6(conn: &mut rusqlite::Connection) -> Result<(), SqliteDbError> {
+    db_exec(conn, |tx| {
+        tx.execute(
+            "ALTER TABLE wallets ADD COLUMN last_poll_timestamp INTEGER",
+            rusqlite::params![],
+        )?;
+        tx.execute("UPDATE version SET version = 6", rusqlite::params![])?;
+        Ok(())
+    })?;
+
+    Ok(())
+}
+
 /// Check the database version and if necessary apply the migrations to upgrade it to the current
 /// one. The `bitcoin_txs` parameter is here for the migration from versions 4 and earlier, which
 /// did not store the Bitcoin transactions in database, to versions 5 and later, which do. For a
@@ -342,6 +355,11 @@ pub fn maybe_apply_migration(
                 migrate_v4_to_v5(&mut conn, bitcoin_txs)?;
                 log::warn!("Migration from database version 4 to version 5 successful.");
             }
+            5 => {
+                log::warn!("Upgrading database from version 5 to version 6.");
+                migrate_v5_to_v6(&mut conn)?;
+                log::warn!("Migration from database version 5 to version 6 successful.");
+            }
             _ => return Err(SqliteDbError::UnsupportedVersion(version)),
         }
     }

src/testutils.rs

@@ -1,7 +1,9 @@
 use crate::{
     bitcoin::{BitcoinInterface, Block, BlockChainTip, MempoolEntry, SyncProgress, UTxO},
     config::{BitcoinConfig, Config},
-    database::{BlockInfo, Coin, CoinStatus, DatabaseConnection, DatabaseInterface, LabelItem},
+    database::{
+        BlockInfo, Coin, CoinStatus, DatabaseConnection, DatabaseInterface, LabelItem, Wallet,
+    },
     descriptors, DaemonControl, DaemonHandle,
 };
 
@@ -149,6 +151,8 @@ struct DummyDbState {
     txs: HashMap<bitcoin::Txid, bitcoin::Transaction>,
     spend_txs: HashMap<bitcoin::Txid, (Psbt, Option<u32>)>,
     timestamp: u32,
+    rescan_timestamp: Option<u32>,
+    last_poll_timestamp: Option<u32>,
 }
 
 pub struct DummyDatabase {
@@ -181,6 +185,8 @@ impl DummyDatabase {
                 txs: HashMap::new(),
                 spend_txs: HashMap::new(),
                 timestamp: now,
+                rescan_timestamp: None,
+                last_poll_timestamp: None,
             })),
         }
     }
@@ -201,6 +207,17 @@ impl DatabaseConnection for DummyDatabase {
         self.db.read().unwrap().curr_tip
     }
 
+    fn wallet(&mut self) -> Wallet {
+        let db_wallet = self.db.read().unwrap();
+        Wallet {
+            timestamp: db_wallet.timestamp,
+            receive_index: db_wallet.deposit_index,
+            change_index: db_wallet.change_index,
+            rescan_timestamp: db_wallet.rescan_timestamp,
+            last_poll_timestamp: db_wallet.last_poll_timestamp,
+        }
+    }
+
     fn timestamp(&mut self) -> u32 {
         self.db.read().unwrap().timestamp
     }
@@ -400,7 +417,7 @@ impl DatabaseConnection for DummyDatabase {
     }
 
     fn rescan_timestamp(&mut self) -> Option<u32> {
-        None
+        self.db.read().unwrap().rescan_timestamp
     }
 
     fn set_rescan(&mut self, _: u32) {
@@ -411,6 +428,14 @@ impl DatabaseConnection for DummyDatabase {
         todo!()
     }
 
+    fn last_poll_timestamp(&mut self) -> Option<u32> {
+        self.db.read().unwrap().last_poll_timestamp
+    }
+
+    fn set_last_poll(&mut self, timestamp: u32) {
+        self.db.write().unwrap().last_poll_timestamp = Some(timestamp);
+    }
+
     fn update_labels(&mut self, _items: &HashMap<LabelItem, Option<String>>) {
         todo!()
     }

tests/test_framework/lianad.py

@@ -38,6 +38,7 @@ class Lianad(TailableProc):
         self.prefix = os.path.split(datadir)[-1]
 
         self.signer = signer
+        self._poll_interval_secs = 1
         self.multi_desc = multi_desc
         self.receive_desc, self.change_desc = multi_desc.singlepath_descriptors()
 
@@ -56,9 +57,14 @@ class Lianad(TailableProc):
 
             f.write("[bitcoin_config]\n")
             f.write('network = "regtest"\n')
-            f.write("poll_interval_secs = 1\n")
+            f.write(f"poll_interval_secs = {self._poll_interval_secs}\n")
         bitcoin_backend.append_to_lianad_conf(self.conf_file)
 
+    @property
+    def poll_interval_secs(self):
+        """Return the poll interval in seconds as defined in the config file."""
+        return self._poll_interval_secs
+
     def finalize_psbt(self, psbt):
         """Create a valid witness for all inputs in the PSBT.
         This will fail if the PSBT input does not contain enough material.

tests/test_rpc.py

@@ -31,6 +31,11 @@ def test_getinfo(lianad):
     assert res["sync"] == 1.0
     assert "main" in res["descriptors"]
     assert res["rescan_progress"] is None
+    last_poll_timestamp = res["last_poll_timestamp"]
+    assert last_poll_timestamp is not None
+    time.sleep(lianad.poll_interval_secs + 1)
+    res = lianad.rpc.getinfo()
+    assert res["last_poll_timestamp"] > last_poll_timestamp
 
 
 def test_getaddress(lianad):