Add logging into cache class

Reviewed By: rafeca

Differential Revision: D7307863

fbshipit-source-id: 0365c5598cd8e56580ebab953dfdcf2d27a59276

packages/metro-cache/package.json

@@ -13,6 +13,7 @@
   },
   "dependencies": {
     "jest-serializer": "^22.4.0",
+    "metro-core": "^0.30.1",
     "mkdirp": "^0.5.1"
   }
 }

packages/metro-cache/src/Cache.js

@@ -10,8 +10,17 @@
 
 'use strict';
 
+const {Logger} = require('metro-core');
+
 import type {CacheStore} from 'metro-cache';
 
+/**
+ * Main cache class. Receives an array of cache instances, and sequentially
+ * traverses them to return a previously stored value. It also ensures setting
+ * the value in all instances.
+ *
+ * All get/set operations are logged via Metro's logger.
+ */
 class Cache<T> {
   _stores: $ReadOnlyArray<CacheStore<T>>;
 
@@ -27,16 +36,40 @@ class Cache<T> {
     const length = stores.length;
 
     for (let i = 0; i < length; i++) {
-      let value = stores[i].get(key);
+      const store = stores[i];
+      const name = store.constructor.name + '::' + key.toString('hex');
+      let value = null;
 
-      if (value instanceof Promise) {
-        value = await value;
-      }
+      const logStart = Logger.log(
+        Logger.createActionStartEntry({
+          action_name: 'Cache get',
+          log_entry_label: name,
+        }),
+      );
 
-      if (value != null) {
-        this._hits.set(key, stores[i]);
+      try {
+        const valueOrPromise = store.get(key);
 
-        return value;
+        if (valueOrPromise && typeof valueOrPromise.then === 'function') {
+          value = await valueOrPromise;
+        } else {
+          value = valueOrPromise;
+        }
+      } finally {
+        Logger.log(Logger.createActionEndEntry(logStart));
+
+        Logger.log(
+          Logger.createEntry({
+            action_name: 'Cache ' + (value == null ? 'miss' : 'hit'),
+            log_entry_label: name,
+          }),
+        );
+
+        if (value != null) {
+          this._hits.set(key, store);
+
+          return value;
+        }
       }
     }
 
@@ -50,6 +83,16 @@ class Cache<T> {
     const promises = [];
 
     for (let i = 0; i < length && stores[i] !== stop; i++) {
+      const store = stores[i];
+      const name = store.constructor.name + '::' + key.toString('hex');
+
+      Logger.log(
+        Logger.createEntry({
+          action_name: 'Cache set',
+          log_entry_label: name,
+        }),
+      );
+
       promises.push(stores[i].set(key, value));
     }
 

packages/metro-cache/src/__tests__/Cache.test.js

@@ -11,18 +11,38 @@
 
 'use strict';
 
-const Cache = require('../Cache');
-
 describe('Cache', () => {
-  function createStore(i) {
-    return {
+  let Cache;
+  let Logger;
+  let log;
+
+  function createStore(name = '') {
+    // eslint-disable-next-line no-eval
+    const TempClass = eval(`(class ${name} {})`);
+
+    return Object.assign(new TempClass(), {
       get: jest.fn().mockImplementation(() => null),
       set: jest.fn(),
-    };
+    });
   }
 
+  beforeEach(() => {
+    Logger = require('metro-core').Logger;
+    Cache = require('../Cache');
+
+    Logger.on('log', item => {
+      log.push({
+        a: item.action_name,
+        l: item.log_entry_label,
+        p: item.action_phase,
+      });
+    });
+
+    log = [];
+  });
+
   afterEach(() => {
-    jest.restoreAllMocks();
+    jest.resetModules().restoreAllMocks();
   });
 
   it('returns null when no result is found', async () => {
@@ -39,9 +59,9 @@ describe('Cache', () => {
   });
 
   it('sequentially searches up until it finds a valid result', async () => {
-    const store1 = createStore(1);
-    const store2 = createStore(2);
-    const store3 = createStore(3);
+    const store1 = createStore();
+    const store2 = createStore();
+    const store3 = createStore();
     const cache = new Cache([store1, store2, store3]);
 
     // Only cache 2 can return results.
@@ -137,4 +157,61 @@ describe('Cache', () => {
 
     expect(error).toBeInstanceOf(TypeError);
   });
+
+  it('logs the right messages when getting without errors', async () => {
+    const store1 = createStore('Local');
+    const store2 = createStore('Network');
+    const cache = new Cache([store1, store2]);
+
+    store1.get.mockImplementation(() => null);
+    store2.get.mockImplementation(() => 'le potato');
+
+    await cache.get(Buffer.from('foo'));
+
+    expect(log).toEqual([
+      {a: 'Cache get', l: 'Cache get', p: 'start'},
+      {a: 'Cache get', l: 'Cache get', p: 'end'},
+      {a: 'Cache miss', l: 'Local::666f6f', p: undefined},
+      {a: 'Cache get', l: 'Cache get', p: 'start'},
+      {a: 'Cache get', l: 'Cache get', p: 'end'},
+      {a: 'Cache hit', l: 'Network::666f6f', p: undefined},
+    ]);
+  });
+
+  it('logs the right messages when getting with errors', async () => {
+    const store1 = createStore('Local');
+    const store2 = createStore('Network');
+    const cache = new Cache([store1, store2]);
+
+    store1.get.mockImplementation(() => null);
+    store2.get.mockImplementation(() => Promise.reject(new TypeError('bar')));
+
+    try {
+      await cache.get(Buffer.from('foo'));
+    } catch (err) {
+      // Do nothing, we care about the logs.
+    }
+
+    expect(log).toEqual([
+      {a: 'Cache get', l: 'Cache get', p: 'start'},
+      {a: 'Cache get', l: 'Cache get', p: 'end'},
+      {a: 'Cache miss', l: 'Local::666f6f', p: undefined},
+      {a: 'Cache get', l: 'Cache get', p: 'start'},
+      {a: 'Cache get', l: 'Cache get', p: 'end'},
+      {a: 'Cache miss', l: 'Network::666f6f', p: undefined},
+    ]);
+  });
+
+  it('logs the right messages when setting', async () => {
+    const store1 = createStore('Local');
+    const store2 = createStore('Network');
+    const cache = new Cache([store1, store2]);
+
+    await cache.set(Buffer.from('foo'));
+
+    expect(log).toEqual([
+      {a: 'Cache set', l: 'Local::666f6f', p: undefined},
+      {a: 'Cache set', l: 'Network::666f6f', p: undefined},
+    ]);
+  });
 });

packages/metro-core/src/Logger/Logger.js

@@ -18,6 +18,7 @@ const VERSION = require('../../package.json').version;
 
 type ActionLogEntryData = {
   action_name: string,
+  log_entry_label?: string,
 };
 
 type ActionStartLogEntry = {