Store log entries on the heap and expose via query call

canister/can.did

@@ -27,5 +27,6 @@ type Result = variant { Ok : nat64; Err : RegisterNeuronPairError };
 service : (InitOrUpgradeArgs) -> {
   deregister_neuron_pair : (DeregisterNeuronPairArgs) -> (bool);
   list_neuron_pairs : () -> (vec NeuronPairPublic) query;
+  logs : () -> (vec text) query;
   register_neuron_pair : (RegisterNeuronPairArgs) -> (Result);
 }

canister/src/jobs/check_for_new_nns_votes.rs

@@ -1,3 +1,4 @@
+use crate::logs::log;
 use crate::{state, NnsVote};
 use candid::CandidType;
 use ic_cdk::api::call::CallResult;
@@ -12,7 +13,7 @@ pub fn start_job() {
 }
 
 async fn run() {
-    ic_cdk::println!("Checking for new NNS votes");
+    log("Checking for new NNS votes");
 
     let futures: Vec<_> = state::mutate(|s| {
         s.iter_neuron_pairs()
@@ -25,7 +26,9 @@ async fn run() {
     let succeeded: usize = results.iter().filter(|success| **success).count();
     let failed = results.len() - succeeded;
 
-    ic_cdk::println!("Check for new NNS votes completed. Succeeded: {succeeded}. Failed: {failed}");
+    log(format!(
+        "Check for new NNS votes completed. Succeeded: {succeeded}. Failed: {failed}"
+    ));
 }
 
 async fn run_single(

canister/src/jobs/process_votes.rs

@@ -1,3 +1,4 @@
+use crate::logs::log;
 use crate::state::State;
 use crate::{state, VoteToProcess, WtnVote};
 use candid::CandidType;
@@ -21,14 +22,14 @@ pub(crate) fn start_job_if_required(state: &State) {
 
 fn run() {
     TIMER_ID.set(None);
-
     if let Some(vote) = state::mutate(|s| s.pop_next_vote_to_process()) {
-        ic_cdk::println!("Processing vote: {vote:?}");
         ic_cdk::spawn(process_vote(vote));
     }
 }
 
 async fn process_vote(vote: VoteToProcess) {
+    log(format!("Processing vote: {vote:?}"));
+
     match vote {
         VoteToProcess::NnsVote(pair_id, nns_vote) => {
             let canister_id = state::read(|s| s.wtn_protocol_canister_id());
@@ -44,14 +45,19 @@ async fn process_vote(vote: VoteToProcess) {
                 )),
                 Ok(Err(latest_processed_nns_proposal_id)) => {
                     if latest_processed_nns_proposal_id.id >= nns_vote.proposal_id {
-                        ic_cdk::println!(
+                        log(format!(
                             "No WTN proposal found for NNS proposal {}",
                             nns_vote.proposal_id
-                        );
+                        ));
                         None
                     } else {
                         // The WTN canister hasn't processed this NNS proposal yet, so put the NNS
                         // proposal back in the queue for it to be attempted again shortly
+                        log(format!(
+                            "WTN canister has not processed NNS proposal yet. ProposalId: {}. Latest processed: {}",
+                            nns_vote.proposal_id,
+                            latest_processed_nns_proposal_id.id
+                        ));
                         Some(VoteToProcess::NnsVote(pair_id, nns_vote))
                     }
                 }

canister/src/lib.rs

@@ -4,6 +4,7 @@ use serde::{Deserialize, Serialize};
 
 mod jobs;
 mod lifecycle;
+mod logs;
 mod memory;
 mod neuron_pair;
 mod queries;

canister/src/lifecycle/init.rs

@@ -1,3 +1,4 @@
+use crate::logs::log;
 use crate::state::State;
 use crate::InitOrUpgradeArgs;
 use ic_cdk::init;
@@ -10,5 +11,5 @@ fn init(args: InitOrUpgradeArgs) {
     crate::jobs::start_jobs(&state);
     crate::state::init(state);
 
-    ic_cdk::println!("Canister initialized");
+    log("Canister initialized");
 }

canister/src/lifecycle/post_upgrade.rs

@@ -1,22 +1,26 @@
 use crate::lifecycle::READER_WRITER_BUFFER_SIZE;
+use crate::logs::log;
 use crate::memory::get_upgrades_memory;
 use crate::state::State;
 use crate::InitOrUpgradeArgs;
 use ic_cdk::post_upgrade;
 use ic_stable_structures::reader::{BufferedReader, Reader};
 use serde::Deserialize;
 
+type Serialized = (State, Vec<String>);
+
 #[post_upgrade]
 fn post_upgrade(args: InitOrUpgradeArgs) {
     let _args = args.into_upgrade_args();
     let memory = get_upgrades_memory();
     let reader = BufferedReader::new(READER_WRITER_BUFFER_SIZE, Reader::new(&memory, 0));
     let mut deserializer = rmp_serde::Deserializer::new(reader);
 
-    let state = State::deserialize(&mut deserializer).unwrap();
+    let (state, logs) = Serialized::deserialize(&mut deserializer).unwrap();
 
     crate::jobs::start_jobs(&state);
     crate::state::init(state);
+    crate::logs::init(logs);
 
-    ic_cdk::println!("Canister upgrade complete");
+    log("Canister upgrade complete");
 }

canister/src/lifecycle/pre_upgrade.rs

@@ -1,4 +1,5 @@
 use crate::lifecycle::READER_WRITER_BUFFER_SIZE;
+use crate::logs::{log, logs};
 use crate::memory::get_upgrades_memory;
 use crate::state;
 use ic_cdk::pre_upgrade;
@@ -7,12 +8,13 @@ use serde::Serialize;
 
 #[pre_upgrade]
 fn pre_upgrade() {
-    ic_cdk::print("Canister upgrade starting");
+    log("Canister upgrade starting");
 
     let mut memory = get_upgrades_memory();
     let writer = BufferedWriter::new(READER_WRITER_BUFFER_SIZE, Writer::new(&mut memory, 0));
     let mut serializer = rmp_serde::Serializer::new(writer).with_struct_map();
 
     let state = state::take();
-    state.serialize(&mut serializer).unwrap()
+    let logs = logs();
+    (state, logs).serialize(&mut serializer).unwrap()
 }

canister/src/logs.rs

@@ -0,0 +1,29 @@
+use std::cell::RefCell;
+use std::collections::VecDeque;
+
+thread_local! {
+    static LOGS: RefCell<VecDeque<String>> = RefCell::default();
+}
+
+pub fn init(logs: Vec<String>) {
+    LOGS.set(VecDeque::from(logs));
+}
+
+pub fn log<S: AsRef<str>>(s: S) {
+    let message = s.as_ref();
+
+    ic_cdk::println!("{message}");
+
+    LOGS.with_borrow_mut(|logs| {
+        let now = ic_cdk::api::time() / 1_000_000;
+        logs.push_back(format!("{now}: {message}"));
+
+        while logs.len() > 1000 {
+            logs.pop_front();
+        }
+    })
+}
+
+pub fn logs() -> Vec<String> {
+    LOGS.with_borrow(|logs| logs.iter().cloned().collect())
+}

canister/src/queries/logs.rs

@@ -0,0 +1,6 @@
+use ic_cdk::query;
+
+#[query]
+fn logs() -> Vec<String> {
+    crate::logs::logs()
+}

canister/src/queries/mod.rs

@@ -1 +1,2 @@
 mod list_neuron_pairs;
+mod logs;

canister/src/state.rs

@@ -1,3 +1,4 @@
+use crate::logs::log;
 use crate::neuron_pair::NeuronPair;
 use crate::{InitArgs, NeuronPairPublic, NnsVote, VoteToProcess, WtnVote};
 use ic_principal::Principal;
@@ -39,12 +40,10 @@ pub fn init(state: State) {
     });
 }
 
-#[allow(dead_code)]
 pub fn read<F: FnOnce(&State) -> R, R>(f: F) -> R {
     STATE.with_borrow(|s| f(s.as_ref().expect(STATE_NOT_INITIALIZED)))
 }
 
-#[allow(dead_code)]
 pub fn mutate<F: FnOnce(&mut State) -> R, R>(f: F) -> R {
     STATE.with_borrow_mut(|s| f(s.as_mut().expect(STATE_NOT_INITIALIZED)))
 }
@@ -136,13 +135,13 @@ impl State {
 
     pub fn record_wtn_vote_registered(&mut self, pair_id: u64, vote: WtnVote) {
         if let Some(pair) = self.neuron_pairs.get_mut(&pair_id) {
-            ic_cdk::println!("WTN vote registered: {vote:?}");
+            log(format!("WTN vote registered: {vote:?}"));
             pair.record_wtn_vote_registered(vote);
         }
     }
 
     pub fn push_vote_to_process(&mut self, vote: VoteToProcess) {
-        ic_cdk::println!("Vote queued for processing: {vote:?}");
+        log(format!("Vote queued for processing: {vote:?}"));
         self.votes_to_process.push_back(vote);
         crate::jobs::process_votes::start_job_if_required(self);
     }