diff --git a/lib/api/LogConfiguration.cpp b/lib/api/LogConfiguration.cpp index 23a7e53cd..0eb6581b2 100644 --- a/lib/api/LogConfiguration.cpp +++ b/lib/api/LogConfiguration.cpp @@ -19,6 +19,7 @@ namespace MAT_NS_BEGIN { { CFG_BOOL_ENABLE_ANALYTICS, false }, { CFG_INT_CACHE_FILE_SIZE, 3145728 }, { CFG_INT_RAM_QUEUE_SIZE, 524288 }, + { CFG_BOOL_ENABLE_BATCHED_STORAGE_FLUSH, true }, { CFG_BOOL_ENABLE_MULTITENANT, true }, { CFG_BOOL_ENABLE_DB_DROP_IF_FULL, false }, { CFG_INT_MAX_TEARDOWN_TIME, 0 }, @@ -51,6 +52,7 @@ namespace MAT_NS_BEGIN { { CFG_BOOL_ENABLE_ANALYTICS, src.enableLifecycleSession }, { CFG_INT_CACHE_FILE_SIZE, src.cacheFileSizeLimitInBytes }, { CFG_INT_RAM_QUEUE_SIZE, src.cacheMemorySizeLimitInBytes }, + { CFG_BOOL_ENABLE_BATCHED_STORAGE_FLUSH, true }, { CFG_BOOL_ENABLE_MULTITENANT, src.multiTenantEnabled }, { CFG_INT_MAX_TEARDOWN_TIME, src.maxTeardownUploadTimeInSec }, { CFG_INT_MAX_PENDING_REQ, src.maxPendingHTTPRequests }, @@ -128,4 +130,3 @@ namespace MAT_NS_BEGIN { } } MAT_NS_END - diff --git a/lib/config/RuntimeConfig_Default.hpp b/lib/config/RuntimeConfig_Default.hpp index 504aeefe3..4b2da9612 100644 --- a/lib/config/RuntimeConfig_Default.hpp +++ b/lib/config/RuntimeConfig_Default.hpp @@ -16,6 +16,7 @@ namespace MAT_NS_BEGIN {CFG_BOOL_ENABLE_ANALYTICS, false}, {CFG_INT_CACHE_FILE_SIZE, 3145728}, {CFG_INT_RAM_QUEUE_SIZE, 524288}, + {CFG_BOOL_ENABLE_BATCHED_STORAGE_FLUSH, true}, {CFG_BOOL_ENABLE_MULTITENANT, true}, {CFG_BOOL_ENABLE_DB_DROP_IF_FULL, false}, {CFG_INT_MAX_TEARDOWN_TIME, 1}, @@ -233,4 +234,3 @@ namespace MAT_NS_BEGIN } MAT_NS_END - diff --git a/lib/include/public/ILogConfiguration.hpp b/lib/include/public/ILogConfiguration.hpp index af1bc44c2..f1119c11d 100644 --- a/lib/include/public/ILogConfiguration.hpp +++ b/lib/include/public/ILogConfiguration.hpp @@ -154,6 +154,12 @@ namespace MAT_NS_BEGIN /// static constexpr const char* const CFG_INT_RAM_QUEUE_BUFFERS = "maxDBFlushQueues"; + /// + /// Batch records when flushing the RAM queue to disk storage. + /// Set to false to use per-record disk stores during flush. + /// + static constexpr const char* const CFG_BOOL_ENABLE_BATCHED_STORAGE_FLUSH = "enableBatchedStorageFlush"; + /// /// SQLite DB will be checkpointed when flushing. /// @@ -481,4 +487,3 @@ namespace MAT_NS_BEGIN } MAT_NS_END #endif - diff --git a/lib/jni/PrivacyGuard_jni.cpp b/lib/jni/PrivacyGuard_jni.cpp index 8fd23867a..5969ffc81 100644 --- a/lib/jni/PrivacyGuard_jni.cpp +++ b/lib/jni/PrivacyGuard_jni.cpp @@ -62,16 +62,22 @@ Java_com_microsoft_applications_events_PrivacyGuard_nativeInitializePrivacyGuard InitializationConfiguration config( reinterpret_cast(iLoggerNativePtr), CommonDataContext{}); + // InitializationConfiguration holds const char* pointers, so the backing + // std::string storage must outlive the PrivacyGuard construction below. + std::string notificationEventName, semanticContextEventName, summaryEventName; if (NotificationEventName != nullptr) { - config.NotificationEventName = JStringToStdString(env, NotificationEventName).c_str(); + notificationEventName = JStringToStdString(env, NotificationEventName); + config.NotificationEventName = notificationEventName.c_str(); } if (SemanticContextEventName != nullptr) { - config.SemanticContextNotificationEventName = JStringToStdString(env, SemanticContextEventName).c_str(); + semanticContextEventName = JStringToStdString(env, SemanticContextEventName); + config.SemanticContextNotificationEventName = semanticContextEventName.c_str(); } if (SummaryEventName != nullptr) { - config.SummaryEventName = JStringToStdString(env, SummaryEventName).c_str(); + summaryEventName = JStringToStdString(env, SummaryEventName); + config.SummaryEventName = summaryEventName.c_str(); } config.UseEventFieldPrefix = static_cast(UseEventFieldPrefix); @@ -119,16 +125,22 @@ Java_com_microsoft_applications_events_PrivacyGuard_nativeInitializePrivacyGuard machineIds, outOfScopeIdentifiers)); + // InitializationConfiguration holds const char* pointers, so the backing + // std::string storage must outlive the PrivacyGuard construction below. + std::string notificationEventName, semanticContextEventName, summaryEventName; if (NotificationEventName != NULL) { - config.NotificationEventName = JStringToStdString(env, NotificationEventName).c_str(); + notificationEventName = JStringToStdString(env, NotificationEventName); + config.NotificationEventName = notificationEventName.c_str(); } if (SemanticContextEventName != NULL) { - config.SemanticContextNotificationEventName = JStringToStdString(env, SemanticContextEventName).c_str(); + semanticContextEventName = JStringToStdString(env, SemanticContextEventName); + config.SemanticContextNotificationEventName = semanticContextEventName.c_str(); } if (SummaryEventName != NULL) { - config.SummaryEventName = JStringToStdString(env, SummaryEventName).c_str(); + summaryEventName = JStringToStdString(env, SummaryEventName); + config.SummaryEventName = summaryEventName.c_str(); } config.UseEventFieldPrefix = static_cast(UseEventFieldPrefix); diff --git a/lib/offline/MemoryStorage.cpp b/lib/offline/MemoryStorage.cpp index 1d4ec5664..77ff0fc7c 100644 --- a/lib/offline/MemoryStorage.cpp +++ b/lib/offline/MemoryStorage.cpp @@ -224,6 +224,16 @@ namespace MAT_NS_BEGIN { void MemoryStorage::DeleteRecords(const std::map & whereFilter) { + // An empty filter matches every record. Never silently wipe the whole + // in-memory queue from a no-op predicate; callers must use + // DeleteAllRecords() for an intentional full clear. This mirrors the + // fail-closed behavior of OfflineStorage_SQLite::DeleteRecords. + if (whereFilter.empty()) + { + LOG_WARN("DeleteRecords called with an empty filter; ignoring to avoid deleting all records."); + return; + } + auto matcher = [&](const StorageRecord &r, const std::map & whereFilter) { bool matched = true; diff --git a/lib/offline/OfflineStorageHandler.cpp b/lib/offline/OfflineStorageHandler.cpp index 9049339c4..20c77c20f 100644 --- a/lib/offline/OfflineStorageHandler.cpp +++ b/lib/offline/OfflineStorageHandler.cpp @@ -9,6 +9,7 @@ #include "offline/MemoryStorage.hpp" #include "ILogManager.hpp" +#include "utils/Utils.hpp" #include #include #include @@ -174,28 +175,42 @@ namespace MAT_NS_BEGIN { // than the handle gets replaced by nullptr in this DeferredCallbackHandle obj. m_flushHandle.Cancel(); - size_t dbSizeBeforeFlush = m_offlineStorageMemory->GetSize(); + size_t dbSizeBeforeFlush = (m_offlineStorageMemory != nullptr) ? m_offlineStorageMemory->GetSize() : 0; if ((m_offlineStorageMemory) && (dbSizeBeforeFlush > 0) && (m_offlineStorageDisk)) { - // This will block on and then take a lock for the duration of this move, and - // StoreRecord() will then block until the move completes. + // Drain the in-memory queue into a local batch. Records are removed + // from memory here; any that fail to persist below are re-inserted, so + // a disk write failure does not silently lose events. Draining (rather + // than reserving) keeps only a single copy of each record in flight and + // avoids stamping a reservation lease that the Room backend would + // persist to disk. auto records = m_offlineStorageMemory->GetRecords(false, EventLatency_Unspecified); - std::vector ids; - // TODO: [MG] - consider running the batch in transaction - // if (sqlite) - // sqlite->Execute("BEGIN"); - - size_t totalSaved = m_offlineStorageDisk->StoreRecords(records); - - // TODO: [MG] - consider running the batch in transaction - // if (sqlite) - // sqlite->Execute("END"); - - // Delete records from reserved on flush - HttpHeaders dummy; - bool fromMemory = true; - m_offlineStorageMemory->DeleteRecords(ids, dummy, fromMemory); + size_t totalSaved = 0; + if (IsBatchedStorageFlushEnabled()) + { + // Persist the drained batch to disk in a single transaction. + // StoreRecords() commits as many records as it durably can and + // returns that count. Records it can never store (e.g. ones failing + // validation, reported separately) are dropped from the batch rather + // than counted, so a return of 0 with records still queued means a + // transient failure committed nothing -- return those records to the + // in-memory queue for retry. No events are lost, and a rolled-back + // batch leaves nothing on disk, so re-queuing cannot create duplicates + // (the events table has no unique record_id constraint). A non-zero + // count means those records are durably stored; do not re-queue. + totalSaved = m_offlineStorageDisk->StoreRecords(records); + if (totalSaved == 0 && !records.empty()) + { + LOG_WARN("Flush: disk store failed for the batch of %zu records; returning to the queue for retry", + records.size()); + ReturnRecordsToMemory(records); + } + } + else + { + totalSaved = StoreRecordsIndividually(records); + } // Notify event listener about the records cached OnStorageRecordsSaved(totalSaved); @@ -210,7 +225,7 @@ namespace MAT_NS_BEGIN { } // Checkpoint DB - if (m_config.HasConfig(CFG_BOOL_CHECKPOINT_DB_ON_FLUSH) && m_config[CFG_BOOL_CHECKPOINT_DB_ON_FLUSH]) + if (m_offlineStorageDisk && m_config.HasConfig(CFG_BOOL_CHECKPOINT_DB_ON_FLUSH) && m_config[CFG_BOOL_CHECKPOINT_DB_ON_FLUSH]) { m_offlineStorageDisk->Flush(); } @@ -244,7 +259,12 @@ namespace MAT_NS_BEGIN { // are selected and removed from the cache (but will // not block for the subsequent handoff to persistent // storage) - m_offlineStorageMemory->StoreRecord(record); + if (!m_offlineStorageMemory->StoreRecord(record)) + { + LOG_ERROR("Failed to store event %s:%s in memory queue", + tenantTokenToId(record.tenantToken).c_str(), record.id.c_str()); + return false; + } } // Perform periodic flush to disk @@ -269,7 +289,9 @@ namespace MAT_NS_BEGIN { { if (record.persistence != EventPersistence::EventPersistence_DoNotStoreOnDisk) { - m_offlineStorageDisk->StoreRecord(record); + // Propagate a synchronous disk write failure to the caller so a + // failed store is not counted as successfully persisted. + return m_offlineStorageDisk->StoreRecord(record); } } } @@ -277,6 +299,95 @@ namespace MAT_NS_BEGIN { return true; } + bool OfflineStorageHandler::IsBatchedStorageFlushEnabled() + { + return !m_config.HasConfig(CFG_BOOL_ENABLE_BATCHED_STORAGE_FLUSH) || + m_config[CFG_BOOL_ENABLE_BATCHED_STORAGE_FLUSH]; + } + + bool OfflineStorageHandler::IsValidDiskRecord(StorageRecord const& record) + { + return !(record.id.empty() || record.tenantToken.empty() || + static_cast(record.latency) < 0 || record.timestamp <= 0); + } + + void OfflineStorageHandler::ReportInvalidDiskRecord(StorageRecord const& record) + { + LOG_ERROR("Flush: dropping event %s:%s: Invalid parameters", + tenantTokenToId(record.tenantToken).c_str(), record.id.c_str()); + OnStorageFailed("Invalid parameters"); + } + + size_t OfflineStorageHandler::StoreRecordsIndividually(std::vector const& records) + { + size_t totalSaved = 0; + std::vector recordsToRetry; + + for (auto it = records.begin(); it != records.end(); ++it) + { + if (!IsValidDiskRecord(*it)) + { + ReportInvalidDiskRecord(*it); + continue; + } + + if (m_offlineStorageDisk->StoreRecord(*it)) + { + ++totalSaved; + continue; + } + + for (auto retryIt = it; retryIt != records.end(); ++retryIt) + { + if (IsValidDiskRecord(*retryIt)) + { + recordsToRetry.push_back(*retryIt); + } + else + { + ReportInvalidDiskRecord(*retryIt); + } + } + break; + } + + if (!recordsToRetry.empty()) + { + LOG_WARN("Flush: per-record disk store failed after saving %zu of %zu records; returning %zu records to the queue for retry", + totalSaved, records.size(), recordsToRetry.size()); + ReturnRecordsToMemory(recordsToRetry); + } + + return totalSaved; + } + + size_t OfflineStorageHandler::ReturnRecordsToMemory(std::vector const& records) + { + size_t returned = 0; + DroppedMap dropped; + + for (auto const& record : records) + { + if (m_offlineStorageMemory && m_offlineStorageMemory->StoreRecord(record)) + { + ++returned; + } + else + { + LOG_ERROR("Flush: failed to return event %s:%s to memory queue after disk store failure; dropping record", + tenantTokenToId(record.tenantToken).c_str(), record.id.c_str()); + dropped[record.tenantToken]++; + } + } + + if (!dropped.empty()) + { + OnStorageRecordsDropped(dropped); + } + + return returned; + } + size_t OfflineStorageHandler::StoreRecords(std::vector& records) { size_t stored = 0; diff --git a/lib/offline/OfflineStorageHandler.hpp b/lib/offline/OfflineStorageHandler.hpp index 1b07d5d1d..10f4c2eb5 100644 --- a/lib/offline/OfflineStorageHandler.hpp +++ b/lib/offline/OfflineStorageHandler.hpp @@ -25,6 +25,8 @@ namespace MAT_NS_BEGIN { class OfflineStorageHandler final : public IOfflineStorage, public IOfflineStorageObserver { + friend class OfflineStorageHandlerTestPeer; + public: OfflineStorageHandler(ILogManager& logManager, IRuntimeConfig& runtimeConfig, ITaskDispatcher& taskDispatcher); virtual ~OfflineStorageHandler() override; @@ -85,8 +87,8 @@ namespace MAT_NS_BEGIN { std::unique_ptr m_offlineStorageMemory; std::shared_ptr m_offlineStorageDisk; - bool m_readFromMemory; - unsigned m_lastReadCount; + std::atomic m_readFromMemory; + std::atomic m_lastReadCount; bool m_shutdownStarted; unsigned m_memoryDbSize; @@ -99,6 +101,11 @@ namespace MAT_NS_BEGIN { private: void WaitForFlush(); + bool IsBatchedStorageFlushEnabled(); + bool IsValidDiskRecord(StorageRecord const& record); + void ReportInvalidDiskRecord(StorageRecord const& record); + size_t StoreRecordsIndividually(std::vector const& records); + size_t ReturnRecordsToMemory(std::vector const& records); }; diff --git a/lib/offline/OfflineStorage_SQLite.cpp b/lib/offline/OfflineStorage_SQLite.cpp index b9b2ed83d..f03ae6be8 100644 --- a/lib/offline/OfflineStorage_SQLite.cpp +++ b/lib/offline/OfflineStorage_SQLite.cpp @@ -23,6 +23,8 @@ namespace MAT_NS_BEGIN { class DbTransaction { SqliteDB* m_db; + bool m_rollback = false; + bool m_finished = false; public: bool locked; @@ -34,11 +36,43 @@ namespace MAT_NS_BEGIN { } } + // Discard the transaction (ROLLBACK) instead of committing it on destruction. + void markForRollback() + { + m_rollback = true; + } + + // Commit the transaction now and report whether COMMIT succeeded. On a + // COMMIT failure the transaction is rolled back so it is never left open, + // and false is returned so the caller does not treat undurable writes as + // stored. After this call the destructor performs no further COMMIT/ROLLBACK. + bool commit() + { + if (!locked || m_finished) + { + return false; + } + m_finished = true; + if (m_db->unlock()) + { + return true; + } + m_db->rollback(); + return false; + } + ~DbTransaction() { - if (locked) + if (locked && !m_finished) { - m_db->unlock(); + if (m_rollback) + { + m_db->rollback(); + } + else + { + m_db->unlock(); + } } } }; @@ -147,40 +181,31 @@ namespace MAT_NS_BEGIN { m_db->execute(command.c_str()); } - bool OfflineStorage_SQLite::StoreRecord(StorageRecord const& record) + bool OfflineStorage_SQLite::isValidRecord(StorageRecord const& record) const { - // TODO: [MG] - this works, but may not play nicely with several LogManager instances - // static SqliteStatement sql_insert(*m_db, m_stmtInsertEvent_id_tenant_prio_ts_data); - if (record.id.empty() || record.tenantToken.empty() || static_cast(record.latency) < 0 || record.timestamp <= 0) { LOG_ERROR("Failed to store event %s:%s: Invalid parameters", tenantTokenToId(record.tenantToken).c_str(), record.id.c_str()); m_observer->OnStorageFailed("Invalid parameters"); return false; } + return true; + } - if (!m_db) { - LOG_ERROR("Failed to store event %s:%s: Database is not open", + bool OfflineStorage_SQLite::insertRecordUnsafe(StorageRecord const& record) + { + if (!SqliteStatement(*m_db, m_stmtInsertEvent_id_tenant_prio_ts_data).execute(record.id, record.tenantToken, static_cast(record.latency), static_cast(record.persistence), record.timestamp, record.blob)) + { + LOG_ERROR("Failed to store event %s:%s: database write failed", tenantTokenToId(record.tenantToken).c_str(), record.id.c_str()); - m_observer->OnStorageOpenFailed("Database is not open"); return false; } + m_DbSizeEstimate += record.id.size() + record.tenantToken.size() + record.blob.size(); + return true; + } - { -#ifdef ENABLE_LOCKING - LOCKGUARD(m_lock); - DbTransaction transaction(m_db.get()); - if (!transaction.locked) - { - LOG_ERROR("Failed to store event %s:%s: Database error", tenantTokenToId(record.tenantToken).c_str(), record.id.c_str()); - m_observer->OnStorageFailed("Database error"); - return false; - } -#endif - SqliteStatement(*m_db, m_stmtInsertEvent_id_tenant_prio_ts_data).execute(record.id, record.tenantToken, static_cast(record.latency), static_cast(record.persistence), record.timestamp, record.blob); - m_DbSizeEstimate += record.id.size() + record.tenantToken.size() + record.blob.size(); - } - + void OfflineStorage_SQLite::checkStorageSizeLimits() + { if ((m_DbSizeNotificationLimit != 0) && (m_DbSizeEstimate>m_DbSizeNotificationLimit)) { auto now = PAL::getMonotonicTimeMs(); @@ -210,20 +235,159 @@ namespace MAT_NS_BEGIN { m_resizing = false; } } + } - return true; + bool OfflineStorage_SQLite::StoreRecord(StorageRecord const& record) + { + // TODO: [MG] - this works, but may not play nicely with several LogManager instances + // static SqliteStatement sql_insert(*m_db, m_stmtInsertEvent_id_tenant_prio_ts_data); + + if (!isValidRecord(record)) { + return false; + } + + if (!m_db) { + LOG_ERROR("Failed to store event %s:%s: Database is not open", + tenantTokenToId(record.tenantToken).c_str(), record.id.c_str()); + m_observer->OnStorageOpenFailed("Database is not open"); + return false; + } + + bool stored = false; + { +#ifdef ENABLE_LOCKING + LOCKGUARD(m_lock); + DbTransaction transaction(m_db.get()); + if (!transaction.locked) + { + LOG_ERROR("Failed to store event %s:%s: Database error", tenantTokenToId(record.tenantToken).c_str(), record.id.c_str()); + m_observer->OnStorageFailed("Database error"); + return false; + } + if (insertRecordUnsafe(record)) + { + // Verify the COMMIT: a COMMIT that fails must not be reported as a + // successful store, or the caller treats an undurable write as saved. + stored = transaction.commit(); + if (!stored) + { + m_DbSizeEstimate -= std::min(m_DbSizeEstimate.load(), + record.id.size() + record.tenantToken.size() + record.blob.size()); + } + } + else + { + transaction.markForRollback(); + } +#else + stored = insertRecordUnsafe(record); +#endif + } + + if (!stored) { + // Report the write failure after the transaction has closed, so the + // observer callback never runs while BEGIN EXCLUSIVE is held. + m_observer->OnStorageFailed("Database write failed"); + } + + // Run the size-limit check after the transaction, matching the original + // per-record path (which ran it on every StoreRecord call). + checkStorageSizeLimits(); + + return stored; } size_t OfflineStorage_SQLite::StoreRecords(std::vector & records) { - size_t stored = 0; - for (auto & i : records) { - if (StoreRecord(i)) { - ++stored; + if (records.empty()) { + return 0; + } + + // Drop invalid records up front (each is reported by isValidRecord) so a + // permanently-invalid record is discarded rather than failing the whole + // batch. Removing them from the vector means a caller that re-queues on a + // short return (e.g. Flush) never re-queues a poison record -- which would + // be re-drained and re-rejected on every flush, blocking every valid record + // behind it -- while the valid remainder stays all-or-nothing. + records.erase( + std::remove_if(records.begin(), records.end(), + [this](StorageRecord const& record) { return !isValidRecord(record); }), + records.end()); + + if (records.empty()) { + // Every record was invalid (already reported). + return 0; + } + + if (!m_db) { + LOG_ERROR("Failed to store %zu events: Database is not open", records.size()); + m_observer->OnStorageOpenFailed("Database is not open"); + return 0; + } + + size_t addedSize = 0; + bool committed = false; + { + // Batch all inserts into a single transaction: one BEGIN EXCLUSIVE / + // COMMIT (one fsync) for the whole flush instead of one per record. + // All-or-nothing: if any insert OR the COMMIT fails the transaction is + // rolled back, so callers (e.g. Flush) can re-queue the whole batch + // without risking duplicate rows (the events table has no unique + // record_id constraint). + bool allInserted = true; +#ifdef ENABLE_LOCKING + LOCKGUARD(m_lock); + DbTransaction transaction(m_db.get()); + if (!transaction.locked) + { + LOG_ERROR("Failed to store %zu events: Database error", records.size()); + m_observer->OnStorageFailed("Database error"); + return 0; + } +#endif + for (auto const& r : records) { + if (insertRecordUnsafe(r)) { + addedSize += r.id.size() + r.tenantToken.size() + r.blob.size(); + } + else { + allInserted = false; + break; + } + } + +#ifdef ENABLE_LOCKING + if (allInserted) { + // Verify the COMMIT: a COMMIT that fails (e.g. SQLITE_FULL/IOERR) + // must not be reported as success, or Flush would drop the records + // it already drained from memory. + committed = transaction.commit(); + } + else { + transaction.markForRollback(); + } +#else + committed = allInserted; +#endif + + if (!committed) { + // Nothing durably stored; undo the size estimate added by the + // (rolled-back) inserts. + m_DbSizeEstimate -= std::min(m_DbSizeEstimate.load(), addedSize); } } - return stored; + + if (!committed) { + // The whole batch was rolled back after an insert or COMMIT failure; + // report once. + m_observer->OnStorageFailed("Database write failed"); + } + + // Run the size-full notification / resize check once after the batch, + // matching the original per-record path (which ran it on every insert). + checkStorageSizeLimits(); + + return committed ? records.size() : 0; } // Debug routine to print record count in the DB diff --git a/lib/offline/OfflineStorage_SQLite.hpp b/lib/offline/OfflineStorage_SQLite.hpp index 18643cde5..1d32a4c77 100644 --- a/lib/offline/OfflineStorage_SQLite.hpp +++ b/lib/offline/OfflineStorage_SQLite.hpp @@ -122,6 +122,15 @@ namespace MAT_NS_BEGIN { private: size_t GetRecordCountUnsafe(EventLatency latency) const; + + // Validate a record's required fields; reports OnStorageFailed on rejection. + bool isValidRecord(StorageRecord const& record) const; + // Insert one already-validated record. Caller must hold m_lock and have an + // active DbTransaction (when ENABLE_LOCKING). Updates m_DbSizeEstimate. + // Returns false (without updating the size estimate) if the insert fails. + bool insertRecordUnsafe(StorageRecord const& record); + // Run the DB-size-full notification and resize checks (after inserts). + void checkStorageSizeLimits(); }; diff --git a/lib/offline/SQLiteWrapper.hpp b/lib/offline/SQLiteWrapper.hpp index 982b4053b..7a2f2170f 100644 --- a/lib/offline/SQLiteWrapper.hpp +++ b/lib/offline/SQLiteWrapper.hpp @@ -219,6 +219,16 @@ namespace MAT_NS_BEGIN { { } + ~SqliteDB() + { + // Finalize prepared statements and close the database even if + // shutdown() was not called explicitly (e.g. the owning storage was + // destroyed without Shutdown()). shutdown() is idempotent -- it + // returns immediately once m_db is null -- so an earlier explicit + // shutdown() makes this a no-op. + shutdown(); + } + bool initialize(std::string const& filename, bool deletePrevious, size_t maxHeapLimit = 0) { int result = SQLITE_OK; @@ -460,6 +470,13 @@ namespace MAT_NS_BEGIN { return isOK(sqlite3_exec("COMMIT;")); } + /** + * @brief Roll back (discard) the current DB transaction. + */ + bool rollback() { + return isOK(sqlite3_exec("ROLLBACK;")); + } + bool lock() { #ifndef NDEBUG unsigned count = 0; diff --git a/lib/tpm/TransmitProfiles.cpp b/lib/tpm/TransmitProfiles.cpp index 5daec5f8b..b26766f6f 100644 --- a/lib/tpm/TransmitProfiles.cpp +++ b/lib/tpm/TransmitProfiles.cpp @@ -58,6 +58,7 @@ static void initTransmitProfileFields() transmitProfilePowerState["unknown"] = (PowerSource_Unknown); transmitProfilePowerState["battery"] = (PowerSource_Battery); transmitProfilePowerState["charging"] = (PowerSource_Charging); + transmitProfilePowerState["low_battery"] = (PowerSource_LowBattery); }; #endif @@ -103,11 +104,14 @@ namespace MAT_NS_BEGIN { LOG_TRACE("name=%s", profile.name.c_str()); size_t i = 0; for (auto &rule : profile.rules) { - LOG_TRACE("[%d] netCost=%2d, powState=%2d, timers=[%3d,%3d,%3d]", + // Custom profiles may supply fewer than three timers, so read + // out-of-range slots as 0 instead of indexing past the vector. + auto timerOrZero = [&rule](size_t idx) { return idx < rule.timers.size() ? rule.timers[idx] : 0; }; + LOG_TRACE("[%zu] netCost=%2d, powState=%2d, timers=[%3d,%3d,%3d]", i, rule.netCost, rule.powerState, - rule.timers[0], - rule.timers[1], - rule.timers[2]); + timerOrZero(0), + timerOrZero(1), + timerOrZero(2)); i++; } } @@ -512,14 +516,17 @@ namespace MAT_NS_BEGIN { isTimerUpdated = true; #ifdef HAVE_MAT_LOGGING auto it = profiles.find(currProfileName); - if (it != profiles.end()) { + if (it != profiles.end() && currRule < it->second.rules.size()) { /* Debug routine to print the list of currently selected timers */ TransmitProfileRule &rule = (it->second).rules[currRule]; + // The rule may carry fewer than three timers, so read out-of-range + // slots as 0 instead of indexing past the vector. + auto timerOrZero = [&rule](size_t idx) { return idx < rule.timers.size() ? rule.timers[idx] : 0; }; // Print just 3 timers for now because we support only 3 LOG_INFO("timers=[%3d,%3d,%3d]", - rule.timers[0], - rule.timers[1], - rule.timers[2]); + timerOrZero(0), + timerOrZero(1), + timerOrZero(2)); } #endif } diff --git a/lib/utils/Utils.cpp b/lib/utils/Utils.cpp index 22a48d87f..b8ac0f6cd 100644 --- a/lib/utils/Utils.cpp +++ b/lib/utils/Utils.cpp @@ -103,15 +103,30 @@ namespace MAT_NS_BEGIN { if (IsRunningInApp()) { auto hr = RoInitialize(RO_INIT_MULTITHREADED); - /* Ignoring result from call to `RoInitialize` as either initialzation is successful, or else already - * initialized and it should be ok to proceed in both the scenarios */ - UNREFERENCED_PARAMETER(hr); - - ::Windows::Storage::StorageFolder ^ temp = ::Windows::Storage::ApplicationData::Current->TemporaryFolder; - // TODO: [MG] - // - verify that the path ends with a slash - // -- add exception handler in case if AppData temp folder is not accessible - return from_platform_string(temp->Path->ToString()); + // RoInitialize returns S_OK when it initializes the apartment and + // S_FALSE when it was already initialized on this thread; both add a + // reference that must be balanced with RoUninitialize. The RAII guard + // balances a successful init on every exit path, including if a WinRT + // call below throws. RPC_E_CHANGED_MODE and other failures did not + // initialize and are left unbalanced. + struct ApartmentGuard + { + HRESULT hr; + ~ApartmentGuard() { if (SUCCEEDED(hr)) { RoUninitialize(); } } + } apartmentGuard{hr}; + + std::string tempPath; + { + // Release the WinRT StorageFolder before the guard runs (at the + // end of the enclosing scope) so the object is not destroyed in an + // uninitialized apartment. + ::Windows::Storage::StorageFolder ^ temp = ::Windows::Storage::ApplicationData::Current->TemporaryFolder; + // TODO: [MG] + // - verify that the path ends with a slash + // -- add exception handler in case if AppData temp folder is not accessible + tempPath = from_platform_string(temp->Path->ToString()); + } + return tempPath; } else { diff --git a/tests/unittests/MemoryStorageTests.cpp b/tests/unittests/MemoryStorageTests.cpp index a736d125f..268cf137d 100644 --- a/tests/unittests/MemoryStorageTests.cpp +++ b/tests/unittests/MemoryStorageTests.cpp @@ -213,6 +213,24 @@ TEST_F(MemoryStorageTests, DeleteAllRecords) EXPECT_THAT(storage.GetReservedCount(), 0); } +TEST_F(MemoryStorageTests, DeleteRecordsWithEmptyFilterDoesNotDeleteAll) +{ + MemoryStorage storage(testLogManager, *testConfig); + + // Add some events to storage + auto total_db_size = addEvents(storage); + EXPECT_THAT(storage.GetSize(), total_db_size); + auto count_before = storage.GetRecordCount(); + EXPECT_GT(count_before, static_cast(0)); + + // An empty where-filter matches every record; it must NOT wipe the queue. + // Intentional full clears go through DeleteAllRecords(). + storage.DeleteRecords(std::map{}); + + EXPECT_THAT(storage.GetRecordCount(), count_before); + EXPECT_THAT(storage.GetSize(), total_db_size); +} + TEST_F(MemoryStorageTests, ReleaseRecords) { diff --git a/tests/unittests/OfflineStorageTests.cpp b/tests/unittests/OfflineStorageTests.cpp index bbb8da8e0..64b4f0320 100644 --- a/tests/unittests/OfflineStorageTests.cpp +++ b/tests/unittests/OfflineStorageTests.cpp @@ -2,7 +2,15 @@ #include "common/Common.hpp" #include "common/MockIOfflineStorage.hpp" +#include "common/MockIOfflineStorageObserver.hpp" +#include "common/MockIRuntimeConfig.hpp" +#include "offline/OfflineStorageHandler.hpp" #include "offline/StorageObserver.hpp" +#include "NullObjects.hpp" + +#include +#include +#include using namespace testing; using namespace MAT; @@ -162,3 +170,276 @@ TEST_F(OfflineStorageTests, ReleaseRecordsIsForwarded) .WillOnce(Return()); EXPECT_THAT(offlineStorage.releaseRecordsIncRetryCount(ctx), true); } + +namespace +{ + // Remove a SQLite db file along with its WAL-mode companion files + // (-wal/-shm/-journal), which would otherwise accumulate in the temp dir. + void RemoveDbFiles(const std::string& path) + { + std::remove(path.c_str()); + std::remove((path + "-wal").c_str()); + std::remove((path + "-shm").c_str()); + std::remove((path + "-journal").c_str()); + } + + // No-op dispatcher that owns queued tasks and frees them, so flushes only + // run when invoked directly and scheduled tasks (if any) are not leaked. + class NoopTaskDispatcher : public ITaskDispatcher + { + public: + void Join() override { clear(); } + void Queue(Task* task) override { m_tasks.push_back(task); } + bool Cancel(Task* task, uint64_t waitTime = 0) override + { + UNREFERENCED_PARAMETER(waitTime); + auto it = std::find(m_tasks.begin(), m_tasks.end(), task); + if (it != m_tasks.end()) + { + delete *it; + m_tasks.erase(it); + return true; + } + return false; + } + ~NoopTaskDispatcher() override { clear(); } + + private: + void clear() + { + for (auto* t : m_tasks) + delete t; + m_tasks.clear(); + } + std::vector m_tasks; + }; +} + +namespace MAT_NS_BEGIN { + + class OfflineStorageHandlerTestPeer + { + public: + static void SetObserver(OfflineStorageHandler& handler, IOfflineStorageObserver& observer) + { + handler.m_observer = &observer; + } + + static void SetMemoryStorage(OfflineStorageHandler& handler, IOfflineStorage* storage) + { + handler.m_offlineStorageMemory.reset(storage); + } + + static void SetDiskStorage(OfflineStorageHandler& handler, std::shared_ptr storage) + { + handler.m_offlineStorageDisk = storage; + } + + static size_t ReturnRecordsToMemory(OfflineStorageHandler& handler, std::vector const& records) + { + return handler.ReturnRecordsToMemory(records); + } + }; + +} MAT_NS_END + +TEST(OfflineStorageHandlerFlushTests, FailedMemoryRequeueIsReportedAndDropped) +{ + NullLogManager logManager; + NiceMock config; + NoopTaskDispatcher dispatcher; + StrictMock observer; + + OfflineStorageHandler handler(logManager, config, dispatcher); + OfflineStorageHandlerTestPeer::SetObserver(handler, observer); + + auto* memory = new StrictMock(); + OfflineStorageHandlerTestPeer::SetMemoryStorage(handler, memory); + + std::vector records; + records.push_back(StorageRecord("retry-ok", "tenant-one-token", + EventLatency_Normal, EventPersistence_Normal, /*timestamp*/ 1, + std::vector{ 'x' })); + records.push_back(StorageRecord("retry-drop", "tenant-two-token", + EventLatency_Normal, EventPersistence_Normal, /*timestamp*/ 1, + std::vector{ 'y' })); + + EXPECT_CALL(*memory, StoreRecord(_)) + .WillOnce(Return(true)) + .WillOnce(Return(false)); + EXPECT_CALL(observer, OnStorageRecordsDropped(_)) + .WillOnce(Invoke([](std::map const& dropped) { + auto found = dropped.find("tenant-two-token"); + ASSERT_NE(found, dropped.end()); + EXPECT_EQ(found->second, static_cast(1)); + })); + + EXPECT_EQ(OfflineStorageHandlerTestPeer::ReturnRecordsToMemory(handler, records), + static_cast(1)); +} + +TEST(OfflineStorageHandlerFlushTests, BatchingOptOutUsesPerRecordDiskStores) +{ + NullLogManager logManager; + NiceMock config; + NoopTaskDispatcher dispatcher; + StrictMock observer; + + config[CFG_BOOL_ENABLE_BATCHED_STORAGE_FLUSH] = false; + + OfflineStorageHandler handler(logManager, config, dispatcher); + OfflineStorageHandlerTestPeer::SetObserver(handler, observer); + + auto* memory = new StrictMock(); + std::shared_ptr> disk(new StrictMock()); + OfflineStorageHandlerTestPeer::SetMemoryStorage(handler, memory); + OfflineStorageHandlerTestPeer::SetDiskStorage(handler, disk); + + std::vector records; + records.push_back(StorageRecord("per-record-1", "tenant-one-token", + EventLatency_Normal, EventPersistence_Normal, /*timestamp*/ 1, + std::vector{ 'x' })); + records.push_back(StorageRecord("per-record-2", "tenant-two-token", + EventLatency_Normal, EventPersistence_Normal, /*timestamp*/ 1, + std::vector{ 'y' })); + + EXPECT_CALL(*memory, GetSize()) + .WillOnce(Return(static_cast(records.size()))) + .WillOnce(Return(static_cast(0))); + EXPECT_CALL(*memory, GetRecords(false, EventLatency_Unspecified, 0)) + .WillOnce(Return(records)); + EXPECT_CALL(*disk, StoreRecords(_)).Times(0); + EXPECT_CALL(*disk, StoreRecord(_)) + .Times(static_cast(records.size())) + .WillRepeatedly(Return(true)); + EXPECT_CALL(observer, OnStorageRecordsSaved(records.size())); + + handler.Flush(); +} + +// Regression test: when valid records drained from the in-memory queue fail to +// be persisted by the disk backend during Flush() (a transient failure -- here +// an unopenable database), they must be returned to the queue rather than lost. +TEST(OfflineStorageHandlerFlushTests, FailedDiskStoreDuringFlushReturnsRecordsToMemory) +{ + NullLogManager logManager; + NiceMock config; + NoopTaskDispatcher dispatcher; + NiceMock observer; + + ON_CALL(config, GetOfflineStorageMaximumSizeBytes()).WillByDefault(Return(32 * 4096)); + ON_CALL(config, GetMaximumRetryCount()).WillByDefault(Return(5)); + + // A path inside a non-existent directory cannot be opened by SQLite (it does + // not create parent directories), so every disk StoreRecords() returns 0 -- + // a transient failure with otherwise-valid records. + std::ostringstream dbPath; + dbPath << GetTempDirectory() << "no_such_dir_" << PAL::getUtcSystemTimeMs() + << "/FlushReserveTest.db"; + config[CFG_STR_CACHE_FILE_PATH] = dbPath.str(); + config[CFG_INT_RAM_QUEUE_SIZE] = 1024 * 1024; // enable the in-memory queue + + OfflineStorageHandler handler(logManager, config, dispatcher); + handler.Initialize(observer); + + const size_t kCount = 5; + for (size_t i = 0; i < kCount; i++) + { + StorageRecord r("flush-id-" + std::to_string(i), "tenant-token", + EventLatency_Normal, EventPersistence_Normal, /*timestamp*/ 1, + std::vector{ 'x' }); + handler.StoreRecord(r); + } + EXPECT_EQ(handler.GetRecordCount(), kCount); + + handler.Flush(); + + // The disk could not persist the batch; with the fix the valid records are + // returned to the in-memory queue rather than silently dropped. + EXPECT_EQ(handler.GetRecordCount(), kCount); + + handler.Shutdown(); +} + +// Regression test: a permanently-invalid record (rejected by the disk backend's +// validation) must be dropped on Flush(), not returned to the queue -- otherwise +// one poison record would be re-drained and re-rejected on every flush, wedging +// the queue and blocking every valid record behind it. +TEST(OfflineStorageHandlerFlushTests, FlushDropsInvalidRecordsInsteadOfWedging) +{ + NullLogManager logManager; + NiceMock config; + NoopTaskDispatcher dispatcher; + NiceMock observer; + + ON_CALL(config, GetOfflineStorageMaximumSizeBytes()).WillByDefault(Return(32 * 4096)); + ON_CALL(config, GetMaximumRetryCount()).WillByDefault(Return(5)); + + std::ostringstream dbPath; + dbPath << GetTempDirectory() << "FlushDropInvalid-" << PAL::getUtcSystemTimeMs() << ".db"; + RemoveDbFiles(dbPath.str()); + config[CFG_STR_CACHE_FILE_PATH] = dbPath.str(); + config[CFG_INT_RAM_QUEUE_SIZE] = 1024 * 1024; // enable the in-memory queue + + OfflineStorageHandler handler(logManager, config, dispatcher); + handler.Initialize(observer); + + // A timestamp <= 0 is accepted by the in-memory queue but permanently rejected + // by the SQLite disk store's validation, so it can never be persisted. + const size_t kCount = 5; + for (size_t i = 0; i < kCount; i++) + { + StorageRecord r("bad-id-" + std::to_string(i), "tenant-token", + EventLatency_Normal, EventPersistence_Normal, /*timestamp*/ 0, + std::vector{ 'x' }); + handler.StoreRecord(r); + } + EXPECT_EQ(handler.GetRecordCount(), kCount); + + handler.Flush(); + + // The invalid records are dropped, not returned to the queue, so the queue + // drains and is not wedged. + EXPECT_EQ(handler.GetRecordCount(), static_cast(0)); + + handler.Shutdown(); + RemoveDbFiles(dbPath.str()); +} + +TEST(OfflineStorageHandlerFlushTests, FlushOptOutDropsInvalidRecordsInsteadOfWedging) +{ + NullLogManager logManager; + NiceMock config; + NoopTaskDispatcher dispatcher; + NiceMock observer; + + ON_CALL(config, GetOfflineStorageMaximumSizeBytes()).WillByDefault(Return(32 * 4096)); + ON_CALL(config, GetMaximumRetryCount()).WillByDefault(Return(5)); + + std::ostringstream dbPath; + dbPath << GetTempDirectory() << "FlushOptOutDropInvalid-" << PAL::getUtcSystemTimeMs() << ".db"; + RemoveDbFiles(dbPath.str()); + config[CFG_STR_CACHE_FILE_PATH] = dbPath.str(); + config[CFG_INT_RAM_QUEUE_SIZE] = 1024 * 1024; + config[CFG_BOOL_ENABLE_BATCHED_STORAGE_FLUSH] = false; + + OfflineStorageHandler handler(logManager, config, dispatcher); + handler.Initialize(observer); + + const size_t kCount = 3; + for (size_t i = 0; i < kCount; i++) + { + StorageRecord r("bad-opt-out-id-" + std::to_string(i), "tenant-token", + EventLatency_Normal, EventPersistence_Normal, /*timestamp*/ 0, + std::vector{ 'x' }); + handler.StoreRecord(r); + } + EXPECT_EQ(handler.GetRecordCount(), kCount); + + handler.Flush(); + + EXPECT_EQ(handler.GetRecordCount(), static_cast(0)); + + handler.Shutdown(); + RemoveDbFiles(dbPath.str()); +} diff --git a/tests/unittests/OfflineStorageTests_SQLite.cpp b/tests/unittests/OfflineStorageTests_SQLite.cpp index e90b0a9ae..b91e65195 100644 --- a/tests/unittests/OfflineStorageTests_SQLite.cpp +++ b/tests/unittests/OfflineStorageTests_SQLite.cpp @@ -153,6 +153,59 @@ TEST_F(OfflineStorageTests_SQLite, GetAndReservedReturnsStoredRecord) EXPECT_THAT(consumer.records[0].reservedUntil, 0); } +TEST_F(OfflineStorageTests_SQLite, StoreRecordsBatchStoresAllRecords) +{ + initializeStorage(); + std::vector batch; + const size_t kCount = 8; + for (size_t i = 0; i < kCount; i++) + { + batch.push_back({ "g" + std::to_string(i), "token", EventLatency_Normal, + EventPersistence_Normal, static_cast(i + 1), { static_cast(i) } }); + } + + // Every record in the batch is stored and individually retrievable. (The + // single-transaction batching is a performance optimization verified by + // benchmarking; this test covers the batch's storage correctness.) + EXPECT_THAT(offlineStorage->StoreRecords(batch), kCount); + + TestRecordConsumer consumer; + EXPECT_THAT(offlineStorage->GetAndReserveRecords(consumer, 100000), true); + ASSERT_THAT(consumer.records.size(), kCount); + for (size_t i = 0; i < kCount; i++) + { + std::string expectedId = "g" + std::to_string(i); + bool found = false; + for (auto const& r : consumer.records) + { + if (r.id == expectedId) { found = true; break; } + } + EXPECT_TRUE(found) << "record " << expectedId << " was not retrieved"; + } +} + +TEST_F(OfflineStorageTests_SQLite, StoreRecordsBatchDropsInvalidAndStoresValid) +{ + initializeStorage(); + std::vector batch = { + { "g1", "token", EventLatency_Normal, EventPersistence_Normal, 1, { 1 } }, // valid + { "g2", "token", EventLatency_Normal, EventPersistence_Normal, 0, { 2 } }, // invalid: timestamp <= 0 + }; + + // The invalid record is reported once during validation. + EXPECT_CALL(observerMock, OnStorageFailed("Invalid parameters")); + + // A permanently-invalid record is dropped (reported once) and the valid + // remainder is still stored. One bad record can never wedge the batch or, via + // a caller that re-queues on a short return (e.g. Flush), block the queue. + EXPECT_THAT(offlineStorage->StoreRecords(batch), static_cast(1)); + + TestRecordConsumer consumer; + EXPECT_THAT(offlineStorage->GetAndReserveRecords(consumer, 100000), true); + ASSERT_THAT(consumer.records.size(), static_cast(1)); + EXPECT_THAT(consumer.records[0].id, "g1"); +} + TEST_F(OfflineStorageTests_SQLite, ReservedRecordIsNotReturned) { initializeStorage(); diff --git a/tests/unittests/TransmitProfilesTests.cpp b/tests/unittests/TransmitProfilesTests.cpp index 58e9d36b5..ce8839de5 100644 --- a/tests/unittests/TransmitProfilesTests.cpp +++ b/tests/unittests/TransmitProfilesTests.cpp @@ -375,6 +375,24 @@ R"([{ ASSERT_TRUE(TransmitProfiles::load(badRule)); } +TEST_F(TransmitProfilesTests, load_Json_RuleWithLowBatteryPowerState_MapsToPowerSourceLowBattery) +{ + // A rule using the "low_battery" powerState must map to PowerSource_LowBattery + // rather than silently falling back to the default PowerSource_Any. + const std::string profile = +R"([{ + "name": "LowBatteryProfile", + "rules": [ + { "powerState": "low_battery", "timers": [ 8, 4, 2 ] } + ] +}])"; + + ASSERT_TRUE(TransmitProfiles::load(profile)); + const auto& rules = TransmitProfiles::profiles[std::string{"LowBatteryProfile"}].rules; + ASSERT_EQ(rules.size(), size_t{1}); + ASSERT_EQ(rules[0].powerState, PowerSource_LowBattery); +} + /* The following tests probably should not pass. But they do.