Plugin Extensions: adds source and id to mutation logs (#107385)

* Plugin Extensions: adds source and id to mutation logs

* chore: fix broken tests

* chore: updates after PR feedback

public/app/features/datasources/components/DataSourcePluginSettings.tsx

@@ -34,7 +34,7 @@ export class DataSourcePluginSettings extends PureComponent<Props> {
       <div>
         {plugin.components.ConfigEditor &&
           createElement(plugin.components.ConfigEditor, {
-            options: writableProxy(dataSource),
+            options: writableProxy(dataSource, { source: 'datasource', pluginId: plugin.meta?.id }),
             onOptionsChange: this.onModelChanged,
           })}
       </div>

public/app/features/plugins/extensions/usePluginComponent.test.tsx

@@ -381,9 +381,12 @@ describe('usePluginComponent()', () => {
     expect(() => render(Component && <Component {...originalProps} override />)).not.toThrow();
 
     // Should log an error in dev mode
-    expect(log.error).toHaveBeenCalledWith('Attempted to mutate object property "c"', {
-      stack: expect.any(String),
-    });
+    expect(log.error).toHaveBeenCalledWith(
+      'Attempted to mutate object property "c" from extension with id myorg-extensions-app',
+      {
+        stack: expect.any(String),
+      }
+    );
   });
 
   it('should pass a writable copy of the props (in production mode)', async () => {
@@ -434,8 +437,11 @@ describe('usePluginComponent()', () => {
     expect(() => render(Component && <Component {...originalProps} override />)).not.toThrow();
 
     // Should log a warning
-    expect(log.warning).toHaveBeenCalledWith('Attempted to mutate object property "c"', {
-      stack: expect.any(String),
-    });
+    expect(log.warning).toHaveBeenCalledWith(
+      'Attempted to mutate object property "c" from extension with id myorg-extensions-app',
+      {
+        stack: expect.any(String),
+      }
+    );
   });
 });

public/app/features/plugins/extensions/usePluginComponents.test.tsx

@@ -266,9 +266,12 @@ describe('usePluginComponents()', () => {
 
     // Should also render the component if it wants to change the props
     expect(() => render(<Component foo={originalFoo} override />)).not.toThrow();
-    expect(log.error).toHaveBeenCalledWith(`Attempted to mutate object property "foo4"`, {
-      stack: expect.any(String),
-    });
+    expect(log.error).toHaveBeenCalledWith(
+      `Attempted to mutate object property "foo4" from extension with id myorg-extensions-app`,
+      {
+        stack: expect.any(String),
+      }
+    );
 
     // Check if the original property hasn't been changed
     expect(originalFoo.foo2.foo3.foo4).toBe('bar');
@@ -327,9 +330,12 @@ describe('usePluginComponents()', () => {
 
     // Should also render the component if it wants to change the props
     expect(() => render(<Component foo={originalFoo} override />)).not.toThrow();
-    expect(log.warning).toHaveBeenCalledWith(`Attempted to mutate object property "foo4"`, {
-      stack: expect.any(String),
-    });
+    expect(log.warning).toHaveBeenCalledWith(
+      `Attempted to mutate object property "foo4" from extension with id myorg-extensions-app`,
+      {
+        stack: expect.any(String),
+      }
+    );
 
     // Check if the original property hasn't been changed
     expect(originalFoo.foo2.foo3.foo4).toBe('bar');

public/app/features/plugins/extensions/utils.test.tsx

@@ -7,7 +7,6 @@ import appEvents from 'app/core/app_events';
 import { ShowModalReactEvent } from 'app/types/events';
 
 import { log } from './logs/log';
-import { resetLogMock } from './logs/testUtils';
 import {
   deepFreeze,
   handleErrorsInFn,
@@ -30,17 +29,17 @@ jest.mock('app/features/plugins/pluginSettings', () => ({
   getPluginSettings: () => Promise.resolve({ info: { version: '1.0.0' } }),
 }));
 
-jest.mock('./logs/log', () => {
-  const { createLogMock } = jest.requireActual('./logs/testUtils');
-  const original = jest.requireActual('./logs/log');
+describe('Plugin Extensions / Utils', () => {
+  beforeEach(() => {
+    jest.spyOn(log, 'error').mockImplementation(() => {});
+    jest.spyOn(log, 'warning').mockImplementation(() => {});
+    jest.spyOn(log, 'debug').mockImplementation(() => {});
+  });
 
-  return {
-    ...original,
-    log: createLogMock(),
-  };
-});
+  afterEach(() => {
+    jest.resetAllMocks();
+  });
 
-describe('Plugin Extensions / Utils', () => {
   describe('deepFreeze()', () => {
     test('should not fail when called with primitive values', () => {
       // Although the type system doesn't allow to call it with primitive values, it can happen that the plugin just ignores these errors.
@@ -386,69 +385,146 @@ describe('Plugin Extensions / Utils', () => {
   });
 
   describe('getMutationObserverProxy()', () => {
-    it('should not be possible to modify values in proxied object, but logs a warning', () => {
-      const proxy = getMutationObserverProxy({ a: 'a' });
+    describe('in development mode', () => {
+      beforeEach(() => {
+        config.buildInfo.env = 'development';
+      });
 
-      expect(() => {
-        proxy.a = 'b';
-      }).not.toThrow();
+      it('should be possible to modify values in proxied object, but logs an error', () => {
+        const proxy = getMutationObserverProxy({ a: 'a' }, { pluginId: 'myorg-cool-datasource', source: 'datasource' });
 
-      expect(log.warning).toHaveBeenCalledWith(`Attempted to mutate object property "a"`, {
-        stack: expect.any(String),
-      });
+        expect(() => {
+          proxy.a = 'b';
+        }).not.toThrow();
 
-      expect(proxy.a).toBe('b');
-    });
+        expect(log.error).toHaveBeenCalledWith(
+          `Attempted to mutate object property "a" from datasource with id myorg-cool-datasource`,
+          {
+            stack: expect.any(String),
+          }
+        );
 
-    it('should be possible to set new values, but logs a debug message', () => {
-      const obj: { a: string; b?: string } = { a: 'a' };
-      const proxy = getMutationObserverProxy(obj);
+        expect(proxy.a).toBe('b');
+      });
 
-      expect(() => {
-        Object.defineProperty(proxy, 'b', {
-          value: 'b',
-          writable: false,
+      it('should be possible to call defineProperty, but logs a debug message', () => {
+        const obj: { a: string; b?: string } = { a: 'a' };
+        const proxy = getMutationObserverProxy(obj, { pluginId: 'myorg-cool-extension' });
+
+        expect(() => {
+          Object.defineProperty(proxy, 'b', {
+            value: 'b',
+            writable: false,
+          });
+        }).not.toThrow();
+
+        expect(log.debug).toHaveBeenCalledWith(
+          `Attempted to define object property "b" from extension with id myorg-cool-extension`,
+          {
+            stack: expect.any(String),
+          }
+        );
+
+        expect(proxy.b).toBe('b');
+      });
+
+      it('should be possible to delete properties, but logs an error', () => {
+        const proxy = getMutationObserverProxy({
+          a: {
+            c: 'c',
+          },
+          b: 'b',
         });
-      }).not.toThrow();
 
-      expect(log.debug).toHaveBeenCalledWith(`Attempted to define object property "b"`, {
-        stack: expect.any(String),
-      });
+        expect(() => {
+          // @ts-ignore - This is to test the logic
+          delete proxy.a.c;
+        }).not.toThrow();
+
+        expect(log.error).toHaveBeenCalledWith(
+          `Attempted to delete object property "c" from extension with id unknown`,
+          {
+            stack: expect.any(String),
+          }
+        );
 
-      expect(proxy.b).toBe('b');
+        expect(proxy.a.c).toBeUndefined();
+      });
     });
 
-    it('should be possible to delete properties, but logs a warning', () => {
-      const proxy = getMutationObserverProxy({
-        a: {
-          c: 'c',
-        },
-        b: 'b',
+    describe('in production mode', () => {
+      beforeEach(() => {
+        config.buildInfo.env = 'production';
       });
 
-      expect(() => {
-        // @ts-ignore - This is to test the logic
-        delete proxy.a.c;
-      }).not.toThrow();
+      it('should be possible to modify values in proxied object, but logs a warning', () => {
+        const proxy = getMutationObserverProxy({ a: 'a' }, { pluginId: 'myorg-cool-datasource', source: 'datasource' });
 
-      expect(log.warning).toHaveBeenCalledWith(`Attempted to delete object property "c"`, {
-        stack: expect.any(String),
+        expect(() => {
+          proxy.a = 'b';
+        }).not.toThrow();
+
+        expect(log.warning).toHaveBeenCalledWith(
+          `Attempted to mutate object property "a" from datasource with id myorg-cool-datasource`,
+          {
+            stack: expect.any(String),
+          }
+        );
+
+        expect(proxy.a).toBe('b');
+      });
+
+      it('should be possible to call defineProperty, but logs a debug message', () => {
+        const obj: { a: string; b?: string } = { a: 'a' };
+        const proxy = getMutationObserverProxy(obj, { pluginId: 'myorg-cool-extension' });
+
+        expect(() => {
+          Object.defineProperty(proxy, 'b', {
+            value: 'b',
+            writable: false,
+          });
+        }).not.toThrow();
+
+        expect(log.debug).toHaveBeenCalledWith(
+          `Attempted to define object property "b" from extension with id myorg-cool-extension`,
+          {
+            stack: expect.any(String),
+          }
+        );
+
+        expect(proxy.b).toBe('b');
       });
 
-      expect(proxy.a.c).toBeUndefined();
+      it('should be possible to delete properties, but logs a warning', () => {
+        const proxy = getMutationObserverProxy({
+          a: {
+            c: 'c',
+          },
+          b: 'b',
+        });
+
+        expect(() => {
+          // @ts-ignore - This is to test the logic
+          delete proxy.a.c;
+        }).not.toThrow();
+
+        expect(log.warning).toHaveBeenCalledWith(
+          `Attempted to delete object property "c" from extension with id unknown`,
+          {
+            stack: expect.any(String),
+          }
+        );
+
+        expect(proxy.a.c).toBeUndefined();
+      });
     });
   });
 
   describe('writableProxy()', () => {
     const originalEnv = config.buildInfo.env;
 
-    beforeEach(() => {
-      jest.spyOn(console, 'warn').mockImplementation();
-    });
-
     afterEach(() => {
       config.buildInfo.env = originalEnv;
-      jest.mocked(console.warn).mockClear();
     });
 
     it('should return the same value for primitive types', () => {
@@ -464,7 +540,7 @@ describe('Plugin Extensions / Utils', () => {
       config.buildInfo.env = 'development';
 
       const obj = { a: 'a' };
-      const copy = writableProxy(obj);
+      const copy = writableProxy(obj, { source: 'datasource', pluginId: 'myorg-cool-datasource' });
 
       expect(copy).not.toBe(obj);
       expect(copy.a).toBe('a');
@@ -473,9 +549,12 @@ describe('Plugin Extensions / Utils', () => {
         copy.a = 'b';
       }).not.toThrow();
 
-      expect(log.warning).toHaveBeenCalledWith(`Attempted to mutate object property "a"`, {
-        stack: expect.any(String),
-      });
+      expect(log.error).toHaveBeenCalledWith(
+        `Attempted to mutate object property "a" from datasource with id myorg-cool-datasource`,
+        {
+          stack: expect.any(String),
+        }
+      );
 
       expect(copy.a).toBe('b');
     });
@@ -484,7 +563,7 @@ describe('Plugin Extensions / Utils', () => {
       config.buildInfo.env = 'production';
 
       const obj = { a: 'a' };
-      const copy = writableProxy(obj);
+      const copy = writableProxy(obj, { source: 'datasource', pluginId: 'myorg-cool-datasource' });
 
       expect(copy).not.toBe(obj);
       expect(copy.a).toBe('a');
@@ -493,9 +572,12 @@ describe('Plugin Extensions / Utils', () => {
         copy.a = 'b';
       }).not.toThrow();
 
-      expect(log.warning).toHaveBeenCalledWith(`Attempted to mutate object property "a"`, {
-        stack: expect.any(String),
-      });
+      expect(log.warning).toHaveBeenCalledWith(
+        `Attempted to mutate object property "a" from datasource with id myorg-cool-datasource`,
+        {
+          stack: expect.any(String),
+        }
+      );
 
       expect(copy.a).toBe('b');
     });
@@ -515,7 +597,7 @@ describe('Plugin Extensions / Utils', () => {
       expect(Object.isFrozen(copy.b)).toBe(true);
       expect(copy.b).toEqual({ c: 'c' });
 
-      expect(log.debug).toHaveBeenCalledWith(`Attempted to define object property "a"`, {
+      expect(log.debug).toHaveBeenCalledWith(`Attempted to define object property "a" from extension with id unknown`, {
         stack: expect.any(String),
       });
     });
@@ -644,10 +726,6 @@ describe('Plugin Extensions / Utils', () => {
       );
     };
 
-    beforeEach(() => {
-      resetLogMock(log);
-    });
-
     it('should make the plugin context available for the wrapped component', async () => {
       const pluginId = 'grafana-worldmap-panel';
       const Component = wrapWithPluginContext(pluginId, ExampleComponent, log);
@@ -674,17 +752,18 @@ describe('Plugin Extensions / Utils', () => {
       const Component = wrapWithPluginContext(pluginId, ExampleComponent, log);
       const props = { a: { b: { c: 'Grafana' } } };
 
-      jest.spyOn(console, 'error').mockImplementation();
-
       render(<Component {...props} override />);
 
       expect(await screen.findByText('Hello Grafana!')).toBeVisible();
 
       // Logs a warning
       expect(log.error).toHaveBeenCalledTimes(1);
-      expect(log.error).toHaveBeenCalledWith(`Attempted to mutate object property "c"`, {
-        stack: expect.any(String),
-      });
+      expect(log.error).toHaveBeenCalledWith(
+        `Attempted to mutate object property "c" from extension with id grafana-worldmap-panel`,
+        {
+          stack: expect.any(String),
+        }
+      );
 
       // Not able to mutate the props in dev mode either
       expect(props.a.b.c).toBe('Grafana');
@@ -702,9 +781,12 @@ describe('Plugin Extensions / Utils', () => {
 
       // Logs a warning
       expect(log.warning).toHaveBeenCalledTimes(1);
-      expect(log.warning).toHaveBeenCalledWith(`Attempted to mutate object property "c"`, {
-        stack: expect.any(String),
-      });
+      expect(log.warning).toHaveBeenCalledWith(
+        `Attempted to mutate object property "c" from extension with id grafana-worldmap-panel`,
+        {
+          stack: expect.any(String),
+        }
+      );
 
       // Not able to mutate the props in production mode either
       expect(props.a.b.c).toBe('Grafana');

public/app/features/plugins/extensions/utils.tsx

@@ -22,7 +22,7 @@ import appEvents from 'app/core/app_events';
 import { getPluginSettings } from 'app/features/plugins/pluginSettings';
 import { OpenExtensionSidebarEvent, ShowModalReactEvent } from 'app/types/events';
 
-import { ExtensionsLog, log } from './logs/log';
+import { ExtensionsLog, log as baseLog } from './logs/log';
 import { AddedLinkRegistryItem } from './registry/AddedLinksRegistry';
 import { assertIsNotPromise, assertLinkPathIsValid, assertStringProps, isPromise } from './validators';
 
@@ -47,7 +47,7 @@ export function createOpenModalFunction(pluginId: string): PluginExtensionEventH
         component: wrapWithPluginContext<ModalWrapperProps>(
           pluginId,
           getModalWrapper({ title, body, width, height }),
-          log
+          baseLog
         ),
       })
     );
@@ -85,7 +85,7 @@ export const wrapWithPluginContext = <T,>(pluginId: string, Component: React.Com
 
     return (
       <PluginContextProvider meta={pluginMeta}>
-        <Component {...writableProxy(props, log)} />
+        <Component {...writableProxy(props, { log, source: 'extension', pluginId })} />
       </PluginContextProvider>
     );
   };
@@ -218,23 +218,35 @@ export function getReadOnlyProxy<T extends object>(obj: T): T {
   });
 }
 
+type MutationSource = 'extension' | 'datasource';
+interface ProxyOptions {
+  log?: ExtensionsLog;
+  source?: MutationSource;
+  pluginId?: string;
+}
+
 /**
  * Returns a proxy that logs any attempted mutation to the original object.
  *
  * @param obj The object to observe
+ * @param options The options for the proxy
+ * @param options.log The logger to use
+ * @param options.source The source of the mutation
+ * @param options.pluginId The id of the plugin that is mutating the object
  * @returns A new proxy object that logs any attempted mutation to the original object
  */
-export function getMutationObserverProxy<T extends object>(obj: T, _log: ExtensionsLog = log): T {
+export function getMutationObserverProxy<T extends object>(obj: T, options?: ProxyOptions): T {
   if (!obj || typeof obj !== 'object' || isMutationObserverProxy(obj)) {
     return obj;
   }
 
+  const { log = baseLog, source = 'extension', pluginId = 'unknown' } = options ?? {};
   const cache = new WeakMap();
-  const logFunction = isGrafanaDevMode() ? _log.error.bind(_log) : _log.warning.bind(_log); // should show error during local development
+  const logFunction = isGrafanaDevMode() ? log.error.bind(log) : log.warning.bind(log); // should show error during local development
 
   return new Proxy(obj, {
     deleteProperty(target, prop) {
-      logFunction(`Attempted to delete object property "${String(prop)}"`, {
+      logFunction(`Attempted to delete object property "${String(prop)}" from ${source} with id ${pluginId}`, {
         stack: new Error().stack ?? '',
       });
       Reflect.deleteProperty(target, prop);
@@ -243,14 +255,14 @@ export function getMutationObserverProxy<T extends object>(obj: T, _log: Extensi
     defineProperty(target, prop, descriptor) {
       // because immer (used by RTK) calls Object.isFrozen and Object.freeze we know that defineProperty will be called
       // behind the scenes as well so we only log message with debug level to minimize the noise and false positives
-      _log.debug(`Attempted to define object property "${String(prop)}"`, {
+      log.debug(`Attempted to define object property "${String(prop)}" from ${source} with id ${pluginId}`, {
         stack: new Error().stack ?? '',
       });
       Reflect.defineProperty(target, prop, descriptor);
       return true;
     },
     set(target, prop, newValue) {
-      logFunction(`Attempted to mutate object property "${String(prop)}"`, {
+      logFunction(`Attempted to mutate object property "${String(prop)}" from ${source} with id ${pluginId}`, {
         stack: new Error().stack ?? '',
       });
       Reflect.set(target, prop, newValue);
@@ -278,7 +290,7 @@ export function getMutationObserverProxy<T extends object>(obj: T, _log: Extensi
 
       if (isObject(value) || isArray(value)) {
         if (!cache.has(value)) {
-          cache.set(value, getMutationObserverProxy(value, _log));
+          cache.set(value, getMutationObserverProxy(value, { log, source, pluginId }));
         }
         return cache.get(value);
       }
@@ -288,14 +300,26 @@ export function getMutationObserverProxy<T extends object>(obj: T, _log: Extensi
   });
 }
 
-export function writableProxy<T>(value: T, _log: ExtensionsLog = log): T {
+/**
+ * Returns a proxy that logs any attempted mutation to the original object.
+ *
+ * @param value The object to observe
+ * @param options The options for the proxy
+ * @param options.log The logger to use
+ * @param options.source The source of the mutation
+ * @param options.pluginId The id of the plugin that is mutating the object
+ * @returns A new proxy object that logs any attempted mutation to the original object
+ */
+export function writableProxy<T>(value: T, options?: ProxyOptions): T {
   // Primitive types are read-only by default
   if (!value || typeof value !== 'object') {
     return value;
   }
 
+  const { log = baseLog, source = 'extension', pluginId = 'unknown' } = options ?? {};
+
   // Default: we return a proxy of a deep-cloned version of the original object, which logs warnings when mutation is attempted
-  return getMutationObserverProxy(cloneDeep(value), _log);
+  return getMutationObserverProxy(cloneDeep(value), { log, pluginId, source });
 }
 
 function isRecord(value: unknown): value is Record<string | number | symbol, unknown> {