diff --git a/src/backend/impl/src/controllers/log_controller.rs b/src/backend/impl/src/controllers/log_controller.rs index 4f62543f..84b703a1 100644 --- a/src/backend/impl/src/controllers/log_controller.rs +++ b/src/backend/impl/src/controllers/log_controller.rs @@ -50,9 +50,7 @@ impl LogController { self.access_control_service .assert_principal_is_admin(&calling_principal)?; - let logs = self.log_service.list_logs(request); - - Ok(logs) + self.log_service.list_logs(request) } } @@ -128,7 +126,7 @@ mod tests { .expect_list_logs() .once() .with(eq(request.clone())) - .return_const(logs.clone()); + .return_const(Ok(logs.clone())); let controller = LogController::new(access_control_service_mock, service_mock); diff --git a/src/backend/impl/src/fixtures/log.rs b/src/backend/impl/src/fixtures/log.rs index d0be3cab..d149dfa8 100644 --- a/src/backend/impl/src/fixtures/log.rs +++ b/src/backend/impl/src/fixtures/log.rs @@ -34,30 +34,6 @@ pub fn log_entry_error() -> LogEntry { } } -#[fixture] -pub fn log_entries() -> Vec { - vec![ - LogEntry { - date_time: date_time_a(), - level: LogLevel::Info, - context: Some("function_a".to_string()), - message: "foo".to_string(), - }, - LogEntry { - date_time: date_time_b(), - level: LogLevel::Warn, - context: Some("function_b".to_string()), - message: "bar".to_string(), - }, - LogEntry { - date_time: date_time_b(), - level: LogLevel::Error, - context: Some("function_c".to_string()), - message: "baz".to_string(), - }, - ] -} - pub mod filters { use crate::repositories::LogsFilter; diff --git a/src/backend/impl/src/repositories/log_repository.rs b/src/backend/impl/src/repositories/log_repository.rs index 703de40c..07a7da45 100644 --- a/src/backend/impl/src/repositories/log_repository.rs +++ b/src/backend/impl/src/repositories/log_repository.rs @@ -1,10 +1,17 @@ -use super::{init_logs, LogEntry, LogId, LogMemory}; +use super::{ + init_log_timestamp_index, init_logs, DateTime, LogEntry, LogId, LogMemory, + LogTimestampIndexMemory, LogTimestampKey, LogTimestampRange, +}; use backend_api::ApiError; use std::cell::RefCell; #[cfg_attr(test, mockall::automock)] pub trait LogRepository { - fn get_logs(&self) -> Vec; + fn get_logs( + &self, + after: Option, + before: Option, + ) -> Result, ApiError>; fn append_log(&self, log_entry: LogEntry) -> Result; } @@ -18,14 +25,34 @@ impl Default for LogRepositoryImpl { } impl LogRepository for LogRepositoryImpl { - fn get_logs(&self) -> Vec { - STATE.with_borrow(|s| s.logs.iter().collect::>()) + fn get_logs( + &self, + after: Option, + before: Option, + ) -> Result, ApiError> { + let range = LogTimestampRange::new(after, before)?; + let logs = STATE.with_borrow(|s| { + s.logs_timestamp_index + .range(range) + .filter_map(|(_, log_id)| { + // the None case should never happen + s.logs.get(log_id) + }) + .collect() + }); + Ok(logs) } fn append_log(&self, log_entry: LogEntry) -> Result { - STATE - .with_borrow_mut(|s| s.logs.append(&log_entry)) - .map_err(|e| ApiError::internal(&format!("Cannot write log: {:?}", e))) + STATE.with_borrow_mut(|s| { + let log_id = s + .logs + .append(&log_entry) + .map_err(|e| ApiError::internal(&format!("Cannot write log: {:?}", e)))?; + let log_key = LogTimestampKey::new(log_entry.date_time, log_id)?; + s.logs_timestamp_index.insert(log_key, log_id); + Ok(log_id) + }) } } @@ -37,11 +64,15 @@ impl LogRepositoryImpl { struct LogState { logs: LogMemory, + logs_timestamp_index: LogTimestampIndexMemory, } impl Default for LogState { fn default() -> Self { - Self { logs: init_logs() } + Self { + logs: init_logs(), + logs_timestamp_index: init_log_timestamp_index(), + } } } @@ -52,23 +83,28 @@ thread_local! { #[cfg(test)] mod tests { use super::*; - use crate::fixtures; + use crate::{fixtures, repositories::LogsFilter}; use rstest::*; #[rstest] - async fn get_logs() { + #[case::before_filter_matching(fixtures::filters::before_filter_matching())] + #[case::before_filter_not_matching(fixtures::filters::before_filter_not_matching())] + #[case::after_filter_matching(fixtures::filters::after_filter_matching())] + #[case::after_filter_not_matching(fixtures::filters::after_filter_not_matching())] + #[case::time_range_filter_matching(fixtures::filters::time_range_filter_matching())] + #[case::time_range_filter_not_matching(fixtures::filters::time_range_filter_not_matching())] + async fn get_logs(#[case] fixture: (LogEntry, LogsFilter, bool)) { + let (log_entry, filter, expected) = fixture; + STATE.set(LogState::default()); - let log_entries = fixtures::log_entries(); let repository = LogRepositoryImpl::default(); + repository.append_log(log_entry.clone()).unwrap(); - for log_entry in log_entries.iter() { - repository.append_log(log_entry.clone()).unwrap(); - } - - let result = repository.get_logs(); + // ranges are tested in the service and controller above + let result = repository.get_logs(filter.after, filter.before).unwrap(); - assert_eq!(result, log_entries); + assert_eq!(result, if expected { vec![log_entry] } else { vec![] }); } #[rstest] diff --git a/src/backend/impl/src/repositories/memories/log_memory.rs b/src/backend/impl/src/repositories/memories/log_memory.rs index 4cab0521..7b343651 100644 --- a/src/backend/impl/src/repositories/memories/log_memory.rs +++ b/src/backend/impl/src/repositories/memories/log_memory.rs @@ -1,14 +1,22 @@ -use super::{Memory, LOGS_INDEX_MEMORY_ID, LOGS_MEMORY_ID, MEMORY_MANAGER}; -use crate::repositories::LogEntry; -use ic_stable_structures::Log; +use super::{ + Memory, LOGS_INDEX_MEMORY_ID, LOGS_MEMORY_ID, LOGS_TIMESTAMP_LEVEL_INDEX_MEMORY_ID, + MEMORY_MANAGER, +}; +use crate::repositories::{LogEntry, LogId, LogTimestampKey}; +use ic_stable_structures::{BTreeMap, Log}; pub type LogMemory = Log; +pub type LogTimestampIndexMemory = BTreeMap; pub fn init_logs() -> LogMemory { // TODO: handle the error LogMemory::init(get_logs_index_memory(), get_logs_memory()).unwrap() } +pub fn init_log_timestamp_index() -> LogTimestampIndexMemory { + LogTimestampIndexMemory::init(get_logs_timestamp_level_index_memory()) +} + fn get_logs_index_memory() -> Memory { MEMORY_MANAGER.with(|m| m.borrow().get(LOGS_INDEX_MEMORY_ID)) } @@ -16,3 +24,7 @@ fn get_logs_index_memory() -> Memory { fn get_logs_memory() -> Memory { MEMORY_MANAGER.with(|m| m.borrow().get(LOGS_MEMORY_ID)) } + +fn get_logs_timestamp_level_index_memory() -> Memory { + MEMORY_MANAGER.with(|m| m.borrow().get(LOGS_TIMESTAMP_LEVEL_INDEX_MEMORY_ID)) +} diff --git a/src/backend/impl/src/repositories/memories/memory_manager.rs b/src/backend/impl/src/repositories/memories/memory_manager.rs index 86738f12..ec158425 100644 --- a/src/backend/impl/src/repositories/memories/memory_manager.rs +++ b/src/backend/impl/src/repositories/memories/memory_manager.rs @@ -28,3 +28,4 @@ pub(super) const PROPOSAL_REVIEW_COMMIT_PROPOSAL_REVIEW_ID_USER_ID_MEMORY_ID: Me pub(super) const IMAGES_MEMORY_ID: MemoryId = MemoryId::new(13); pub(super) const PROPOSAL_NERVOUS_SYSTEM_ID_INDEX_MEMORY_ID: MemoryId = MemoryId::new(14); pub(super) const PROPOSAL_TIMESTAMP_INDEX_MEMORY_ID: MemoryId = MemoryId::new(15); +pub(super) const LOGS_TIMESTAMP_LEVEL_INDEX_MEMORY_ID: MemoryId = MemoryId::new(16); diff --git a/src/backend/impl/src/repositories/types/log.rs b/src/backend/impl/src/repositories/types/log.rs index d42e3a49..ab286664 100644 --- a/src/backend/impl/src/repositories/types/log.rs +++ b/src/backend/impl/src/repositories/types/log.rs @@ -1,7 +1,11 @@ use super::DateTime; +use backend_api::ApiError; use candid::{CandidType, Decode, Deserialize, Encode}; -use ic_stable_structures::{storable::Bound, Storable}; -use std::borrow::Cow; +use ic_stable_structures::{ + storable::{Blob, Bound}, + Storable, +}; +use std::{borrow::Cow, ops::RangeBounds}; pub type LogId = u64; @@ -16,18 +20,6 @@ pub struct LogsFilter { impl LogsFilter { pub fn matches(&self, log_entry: &LogEntry) -> bool { - if let Some(before) = &self.before { - if log_entry.date_time > *before { - return false; - } - } - - if let Some(after) = &self.after { - if log_entry.date_time < *after { - return false; - } - } - if let Some(level) = &self.level { if log_entry.level != *level { return false; @@ -82,10 +74,77 @@ impl Storable for LogEntry { const BOUND: Bound = Bound::Unbounded; } +#[derive(Debug, Clone, PartialEq, Eq, PartialOrd, Ord)] +pub struct LogTimestampKey(Blob<{ Self::MAX_SIZE as usize }>); + +impl LogTimestampKey { + const MAX_SIZE: u32 = <(DateTime, LogId)>::BOUND.max_size(); + + pub fn new(date_time: DateTime, log_id: LogId) -> Result { + Ok(Self( + Blob::try_from((date_time, log_id).to_bytes().as_ref()).map_err(|_| { + ApiError::internal(&format!( + "Failed to convert date time {:?} and log id {} to bytes.", + date_time, log_id + )) + })?, + )) + } +} + +impl Storable for LogTimestampKey { + fn to_bytes(&self) -> Cow<[u8]> { + self.0.to_bytes() + } + + fn from_bytes(bytes: Cow<[u8]>) -> Self { + Self(Blob::from_bytes(bytes)) + } + + const BOUND: Bound = Bound::Bounded { + max_size: Self::MAX_SIZE, + is_fixed_size: true, + }; +} + +pub struct LogTimestampRange { + start_bound: LogTimestampKey, + end_bound: LogTimestampKey, +} + +impl LogTimestampRange { + pub fn new( + min_date_time: Option, + max_date_time: Option, + ) -> Result { + let max_date_time = match max_date_time { + Some(max_date_time) => max_date_time, + None => DateTime::max()?, + }; + Ok(Self { + start_bound: LogTimestampKey::new( + min_date_time.unwrap_or_else(DateTime::min), + LogId::MIN, + )?, + end_bound: LogTimestampKey::new(max_date_time, LogId::MAX)?, + }) + } +} + +impl RangeBounds for LogTimestampRange { + fn start_bound(&self) -> std::ops::Bound<&LogTimestampKey> { + std::ops::Bound::Included(&self.start_bound) + } + + fn end_bound(&self) -> std::ops::Bound<&LogTimestampKey> { + std::ops::Bound::Included(&self.end_bound) + } +} + #[cfg(test)] mod tests { use super::*; - use crate::fixtures; + use crate::{fixtures, system_api::get_date_time}; use rstest::*; #[rstest] @@ -99,23 +158,27 @@ mod tests { #[rstest] #[case::empty_filter(fixtures::filters::empty_filter())] - #[case::before_filter_matching(fixtures::filters::before_filter_matching())] - #[case::before_filter_not_matching(fixtures::filters::before_filter_not_matching())] - #[case::after_filter_matching(fixtures::filters::after_filter_matching())] - #[case::after_filter_not_matching(fixtures::filters::after_filter_not_matching())] - #[case::time_range_filter_matching(fixtures::filters::time_range_filter_matching())] - #[case::time_range_filter_not_matching(fixtures::filters::time_range_filter_not_matching())] #[case::level_filter_matching(fixtures::filters::level_filter_matching())] #[case::level_filter_not_matching(fixtures::filters::level_filter_not_matching())] #[case::context_filter_matching(fixtures::filters::context_filter_matching())] #[case::context_filter_not_matching(fixtures::filters::context_filter_not_matching())] #[case::message_filter_matching(fixtures::filters::message_filter_matching())] - #[case::message_filter_not_matchingd(fixtures::filters::message_filter_not_matching())] - #[case::all_matching(fixtures::filters::all_matching())] - #[case::all_not_matching(fixtures::filters::all_not_matching())] + #[case::message_filter_not_matching(fixtures::filters::message_filter_not_matching())] fn filter_matches(#[case] fixture: (LogEntry, LogsFilter, bool)) { let (log_entry, filter, expected) = fixture; assert_eq!(filter.matches(&log_entry), expected); } + + #[rstest] + fn log_timestamp_key_storable_impl() { + let date_time = get_date_time().unwrap(); + let log_id: LogId = 1234; + + let key = LogTimestampKey::new(DateTime::new(date_time).unwrap(), log_id).unwrap(); + let serialized_key = key.to_bytes(); + let deserialized_key = LogTimestampKey::from_bytes(serialized_key); + + assert_eq!(key, deserialized_key); + } } diff --git a/src/backend/impl/src/services/log_service.rs b/src/backend/impl/src/services/log_service.rs index 8860df9f..ec7b2ae3 100644 --- a/src/backend/impl/src/services/log_service.rs +++ b/src/backend/impl/src/services/log_service.rs @@ -7,7 +7,7 @@ use backend_api::{ApiError, ListLogsResponse, LogsFilterRequest}; #[cfg_attr(test, mockall::automock)] pub trait LogService { - fn list_logs(&self, filter: LogsFilterRequest) -> ListLogsResponse; + fn list_logs(&self, filter: LogsFilterRequest) -> Result; fn append_log( &self, @@ -34,18 +34,18 @@ impl Default for LogServiceImpl { } impl LogService for LogServiceImpl { - fn list_logs(&self, request: LogsFilterRequest) -> ListLogsResponse { + fn list_logs(&self, request: LogsFilterRequest) -> Result { let filter = map_logs_filter_request(request); let logs = self .log_repository - .get_logs() + .get_logs(filter.after, filter.before)? .iter() .filter(|l| filter.matches(l)) .cloned() .collect::>(); - map_list_logs_response(logs) + Ok(map_list_logs_response(logs)) } fn append_log( @@ -103,11 +103,11 @@ mod tests { repository_mock .expect_get_logs() .once() - .return_const(vec![log_entry.clone(), log_entry.clone()]); + .return_const(Ok(vec![log_entry.clone(), log_entry.clone()])); let service = LogServiceImpl::new(repository_mock); - let result = service.list_logs(filter.into()); + let result = service.list_logs(filter.into()).unwrap(); assert_eq!( result, @@ -133,15 +133,13 @@ mod tests { fn list_logs(#[case] fixture: (LogEntry, LogsFilter, bool)) { let (log_entry, filter, expected) = fixture; - let mut repository_mock = MockLogRepository::new(); - repository_mock - .expect_get_logs() - .once() - .return_const(vec![log_entry.clone()]); + // We want to use the real repository in order to test all the filters properly + let repository = LogRepositoryImpl::default(); + repository.append_log(log_entry.clone()).unwrap(); - let service = LogServiceImpl::new(repository_mock); + let service = LogServiceImpl::new(repository); - let result = service.list_logs(filter.into()); + let result = service.list_logs(filter.into()).unwrap(); assert_eq!( result, diff --git a/src/backend/logs/src/fetcher.rs b/src/backend/logs/src/fetcher.rs index 7476ad11..66295e0f 100644 --- a/src/backend/logs/src/fetcher.rs +++ b/src/backend/logs/src/fetcher.rs @@ -8,7 +8,7 @@ use backend_api::{ApiResult, ListLogsResponse, LogEntry, LogsFilterRequest}; use candid::{Decode, Encode, Principal}; use ic_agent::{identity::Secp256k1Identity, Agent}; -use crate::utils::now_timestamp_ms; +use crate::utils::{now_timestamp_ms, FIVE_MINUTES_MS}; struct BackendActor { agent: Agent, @@ -25,12 +25,9 @@ impl BackendActor { Ok(Self { agent, canister_id }) } - async fn list_logs( - &self, - after_timestamp_ms: Option, - ) -> Result { + async fn list_logs(&self, after_timestamp_ms: u64) -> Result { let request = LogsFilterRequest { - after_timestamp_ms, + after_timestamp_ms: Some(after_timestamp_ms), before_timestamp_ms: None, context_contains_any: None, level: None, @@ -50,12 +47,15 @@ impl BackendActor { } pub struct LogFetcher { - last_fetch_timestamp: Option, + last_fetch_timestamp: u64, file: File, actor: BackendActor, } impl LogFetcher { + /// Creates a new log fetcher by loading the last fetch timestamp from the file `data/last-fetch-timestamp.txt`. + /// + /// If the file does not exist, the last fetch timestamp is set to the current timestamp minus 5 minutes. pub fn new(identity_pem: PathBuf, backend_canister_id: String) -> anyhow::Result { let path = "data/last-fetch-timestamp.txt"; let mut file = OpenOptions::new() @@ -70,7 +70,10 @@ impl LogFetcher { Ok(Self { file, - last_fetch_timestamp: last_fetch_timestamp.trim().parse().ok(), + last_fetch_timestamp: last_fetch_timestamp + .trim() + .parse() + .unwrap_or_else(|_| now_timestamp_ms() - FIVE_MINUTES_MS), actor, }) } @@ -83,7 +86,7 @@ impl LogFetcher { } fn update_last_fetch_timestamp(&mut self, timestamp: u64) { - self.last_fetch_timestamp = Some(timestamp); + self.last_fetch_timestamp = timestamp; self.file.set_len(0).unwrap(); self.file.rewind().unwrap(); self.file diff --git a/src/backend/logs/src/utils.rs b/src/backend/logs/src/utils.rs index a4d1ac0e..6073bb75 100644 --- a/src/backend/logs/src/utils.rs +++ b/src/backend/logs/src/utils.rs @@ -1,5 +1,7 @@ use std::time::{SystemTime, UNIX_EPOCH}; +pub const FIVE_MINUTES_MS: u64 = 5 * 60 * 1_000; + pub fn now() -> SystemTime { SystemTime::now() }