Merge pull request #771 from callstack-internal/feat/87780-improve-logging

feat: Improve retryOperation and reportStorageQuota logging to include original error

Author: tgolen

lib/OnyxUtils.ts

@@ -763,13 +763,13 @@ function remove<TKey extends OnyxKey>(key: TKey, isProcessingCollectionUpdate?:
     return Storage.removeItem(key).then(() => undefined);
 }
 
-function reportStorageQuota(): Promise<void> {
+function reportStorageQuota(error?: Error): Promise<void> {
     return Storage.getDatabaseSize()
         .then(({bytesUsed, bytesRemaining}) => {
-            Logger.logInfo(`Storage Quota Check -- bytesUsed: ${bytesUsed} bytesRemaining: ${bytesRemaining}`);
+            Logger.logInfo(`Storage Quota Check -- bytesUsed: ${bytesUsed} bytesRemaining: ${bytesRemaining}. Original error: ${error}`);
         })
         .catch((dbSizeError) => {
-            Logger.logAlert(`Unable to get database size. Error: ${dbSizeError}`);
+            Logger.logAlert(`Unable to get database size. getDatabaseSize error: ${dbSizeError}. Original error: ${error}`);
         });
 }
 
@@ -786,7 +786,7 @@ function retryOperation<TMethod extends RetriableOnyxOperation>(error: Error, on
     Logger.logInfo(`Failed to save to storage. Error: ${error}. onyxMethod: ${onyxMethod.name}. retryAttempt: ${currentRetryAttempt}/${MAX_STORAGE_OPERATION_RETRY_ATTEMPTS}`);
 
     if (error && Str.startsWith(error.message, "Failed to execute 'put' on 'IDBObjectStore'")) {
-        Logger.logAlert('Attempted to set invalid data set in Onyx. Please ensure all data is serializable.');
+        Logger.logAlert(`Attempted to set invalid data set in Onyx. Please ensure all data is serializable. Error: ${error}`);
         throw error;
     }
 
@@ -810,13 +810,13 @@ function retryOperation<TMethod extends RetriableOnyxOperation>(error: Error, on
         // If we have no acceptable keys to remove then we are possibly trying to save mission critical data. If this is the case,
         // then we should stop retrying as there is not much the user can do to fix this. Instead of getting them stuck in an infinite loop we
         // will allow this write to be skipped.
-        Logger.logAlert('Out of storage. But found no acceptable keys to remove.');
-        return reportStorageQuota();
+        Logger.logAlert(`Out of storage. But found no acceptable keys to remove. Error: ${error}`);
+        return reportStorageQuota(error);
     }
 
     // Remove the least recently accessed key and retry.
-    Logger.logInfo(`Out of storage. Evicting least recently accessed key (${keyForRemoval}) and retrying.`);
-    reportStorageQuota();
+    Logger.logInfo(`Out of storage. Evicting least recently accessed key (${keyForRemoval}) and retrying. Error: ${error}`);
+    reportStorageQuota(error);
 
     // @ts-expect-error No overload matches this call.
     return remove(keyForRemoval).then(() => onyxMethod(defaultParams, nextRetryAttempt));

tests/unit/onyxUtilsTest.ts

@@ -6,6 +6,7 @@ import utils from '../../lib/utils';
 import type {Collection, OnyxCollection} from '../../lib/types';
 import type GenericCollection from '../utils/GenericCollection';
 import OnyxCache from '../../lib/OnyxCache';
+import * as Logger from '../../lib/Logger';
 import StorageMock from '../../lib/storage';
 import createDeferredTask from '../../lib/createDeferredTask';
 import waitForPromisesToResolve from '../utils/waitForPromisesToResolve';
@@ -463,6 +464,37 @@ describe('OnyxUtils', () => {
             expect(retryOperationSpy).toHaveBeenCalledTimes(1);
         });
 
+        it('should include the error in logAlert for IDBObjectStore invalid data errors', async () => {
+            const logAlertSpy = jest.spyOn(Logger, 'logAlert');
+            StorageMock.setItem = jest.fn().mockRejectedValueOnce(invalidDataError);
+
+            await expect(Onyx.set(ONYXKEYS.TEST_KEY, {test: 'data'})).rejects.toThrow(invalidDataError);
+
+            expect(logAlertSpy).toHaveBeenCalledWith(`Attempted to set invalid data set in Onyx. Please ensure all data is serializable. Error: ${invalidDataError}`);
+        });
+
+        it('should include the error in logs when out of storage with no evictable keys', async () => {
+            const logAlertSpy = jest.spyOn(Logger, 'logAlert');
+            const logInfoSpy = jest.spyOn(Logger, 'logInfo');
+            StorageMock.setItem = jest.fn().mockRejectedValue(diskFullError);
+
+            await Onyx.set(ONYXKEYS.TEST_KEY, {test: 'data'});
+
+            expect(logAlertSpy).toHaveBeenCalledWith(`Out of storage. But found no acceptable keys to remove. Error: ${diskFullError}`);
+            expect(logInfoSpy).toHaveBeenCalledWith(`Storage Quota Check -- bytesUsed: 0 bytesRemaining: Infinity. Original error: ${diskFullError}`);
+        });
+
+        it('should include the error in logAlert when out of storage and getDatabaseSize fails', async () => {
+            const dbSizeError = new Error('Failed to estimate storage');
+            const logAlertSpy = jest.spyOn(Logger, 'logAlert');
+            StorageMock.setItem = jest.fn().mockRejectedValue(diskFullError);
+            StorageMock.getDatabaseSize = jest.fn().mockRejectedValue(dbSizeError);
+
+            await Onyx.set(ONYXKEYS.TEST_KEY, {test: 'data'});
+
+            expect(logAlertSpy).toHaveBeenCalledWith(`Unable to get database size. getDatabaseSize error: ${dbSizeError}. Original error: ${diskFullError}`);
+        });
+
         it('should not re-add an evicted key to recentlyAccessedKeys after removal', async () => {
             // Re-init with evictable keys so getKeyForEviction() has something to return
             Object.assign(OnyxUtils.getDeferredInitTask(), createDeferredTask());
@@ -490,6 +522,7 @@ describe('OnyxUtils', () => {
         let LocalOnyxUtils: typeof OnyxUtils;
         let LocalOnyxCache: typeof OnyxCache;
         let LocalStorageMock: typeof StorageMock;
+        let LocalLogger: typeof Logger;
 
         // Reset all modules to get fresh singletons (OnyxCache, OnyxUtils, etc.)
         // then re-init Onyx with evictableKeys configured
@@ -500,6 +533,7 @@ describe('OnyxUtils', () => {
             LocalOnyxUtils = require('../../lib/OnyxUtils').default;
             LocalOnyxCache = require('../../lib/OnyxCache').default;
             LocalStorageMock = require('../../lib/storage').default;
+            LocalLogger = require('../../lib/Logger');
 
             LocalOnyx.init({
                 keys: ONYXKEYS,
@@ -605,6 +639,20 @@ describe('OnyxUtils', () => {
             expect(keyForEviction).toBeDefined();
             expect(keyForEviction?.startsWith(ONYXKEYS.COLLECTION.TEST_KEY)).toBe(true);
         });
+
+        it('should include the error in logs when evicting a key', async () => {
+            const logInfoSpy = jest.spyOn(LocalLogger, 'logInfo');
+            const key1 = `${ONYXKEYS.COLLECTION.TEST_KEY}1`;
+
+            await LocalOnyx.set(key1, {id: 1});
+
+            LocalStorageMock.setItem = jest.fn(LocalStorageMock.setItem).mockRejectedValueOnce(diskFullError).mockImplementation(LocalStorageMock.setItem);
+
+            await LocalOnyx.set(ONYXKEYS.TEST_KEY, {test: 'data'});
+
+            expect(logInfoSpy).toHaveBeenCalledWith(`Out of storage. Evicting least recently accessed key (${key1}) and retrying. Error: ${diskFullError}`);
+            expect(logInfoSpy).toHaveBeenCalledWith(`Storage Quota Check -- bytesUsed: 0 bytesRemaining: Infinity. Original error: ${diskFullError}`);
+        });
     });
 
     describe('afterInit', () => {