Make sure exceptions and console.errors are send to metro

Summary: changelog: [General] `console.error` calls, and uncaught exceptions are now displayed in the Metro logs as well

Reviewed By: passy

Differential Revision: D19743075

fbshipit-source-id: a665a06cfc7854ae785af177af8f2478bb1d76b0

Author: mweststrate

Libraries/Core/ExceptionsManager.js

@@ -52,7 +52,11 @@ function preprocessException(data: ExceptionData): ExceptionData {
  * Handles the developer-visible aspect of errors and exceptions
  */
 let exceptionID = 0;
-function reportException(e: ExtendedError, isFatal: boolean) {
+function reportException(
+  e: ExtendedError,
+  isFatal: boolean,
+  reportToConsole: boolean, // only true when coming from handleException; the error has not yet been logged
+) {
   const NativeExceptionsManager = require('./NativeExceptionsManager').default;
   if (NativeExceptionsManager) {
     const parseErrorStack = require('./Devtools/parseErrorStack');
@@ -64,21 +68,11 @@ function reportException(e: ExtendedError, isFatal: boolean) {
       message += `\n\nThis error is located at:${e.componentStack}`;
     }
     const namePrefix = e.name == null || e.name === '' ? '' : `${e.name}: `;
-    const isFromConsoleError = e.name === 'console.error';
 
     if (!message.startsWith(namePrefix)) {
       message = namePrefix + message;
     }
 
-    // Errors created by `console.error` have already been printed.
-    if (!isFromConsoleError) {
-      if (console._errorOriginal) {
-        console._errorOriginal(message);
-      } else {
-        console.error(message);
-      }
-    }
-
     message =
       e.jsEngine == null ? message : `${message}, js engine: ${e.jsEngine}`;
 
@@ -104,6 +98,13 @@ function reportException(e: ExtendedError, isFatal: boolean) {
       },
     });
 
+    if (reportToConsole) {
+      // we feed back into console.error, to make sure any methods that are
+      // monkey patched on top of console.error are called when coming from
+      // handleException
+      console.error(data.message);
+    }
+
     if (isHandledByLogBox) {
       LogBoxData.addException({
         ...data,
@@ -134,6 +135,11 @@ function reportException(e: ExtendedError, isFatal: boolean) {
           console.log('Unable to symbolicate stack trace: ' + error.message);
         });
     }
+  } else if (reportToConsole) {
+    // we feed back into console.error, to make sure any methods that are
+    // monkey patched on top of console.error are called when coming from
+    // handleException
+    console.error(e);
   }
 }
 
@@ -143,6 +149,10 @@ declare var console: typeof console & {
   ...
 };
 
+// If we trigger console.error _from_ handleException,
+// we do want to make sure that console.error doesn't trigger error reporting again
+let inExceptionHandler = false;
+
 /**
  * Logs exceptions to the (native) console and displays them
  */
@@ -157,20 +167,60 @@ function handleException(e: mixed, isFatal: boolean) {
     // `throw '<error message>'` somewhere in your codebase.
     error = new SyntheticError(e);
   }
-  reportException(error, isFatal);
+  try {
+    inExceptionHandler = true;
+    reportException(error, isFatal, /*reportToConsole*/ true);
+  } finally {
+    inExceptionHandler = false;
+  }
 }
 
 function reactConsoleErrorHandler() {
+  // bubble up to any original handlers
+  console._errorOriginal.apply(console, arguments);
   if (!console.reportErrorsAsExceptions) {
-    console._errorOriginal.apply(console, arguments);
+    return;
+  }
+  if (inExceptionHandler) {
+    // The fundamental trick here is that are multiple entry point to logging errors:
+    // (see D19743075 for more background)
+    //
+    // 1. An uncaught exception being caught by the global handler
+    // 2. An error being logged throw console.error
+    //
+    // However, console.error is monkey patched multiple times: by this module, and by the
+    // DevTools setup that sends messages to Metro.
+    // The patching order cannot be relied upon.
+    //
+    // So, some scenarios that are handled by this flag:
+    //
+    // Logging an error:
+    // 1. console.error called from user code
+    // 2. (possibly) arrives _first_ at DevTool handler, send to Metro
+    // 3. Bubbles to here
+    // 4. goes into report Exception.
+    // 5. should not trigger console.error again, to avoid looping / logging twice
+    // 6. should still bubble up to original console
+    //    (which might either be console.log, or the DevTools handler in case it patched _earlier_ and (2) didn't happen)
+    //
+    // Throwing an uncaught exception:
+    // 1. exception thrown
+    // 2. picked up by handleException
+    // 3. should be send to console.error (not console._errorOriginal, as DevTools might have patched _later_ and it needs to send it to Metro)
+    // 4. that _might_ bubble again to the `reactConsoleErrorHandle` defined here
+    //    -> should not handle exception _again_, to avoid looping / showing twice (this code branch)
+    // 5. should still bubble up to original console (which might either be console.log, or the DevTools handler in case that one patched _earlier_)
     return;
   }
 
   if (arguments[0] && arguments[0].stack) {
     // reportException will console.error this with high enough fidelity.
-    reportException(arguments[0], /* isFatal */ false);
+    reportException(
+      arguments[0],
+      /* isFatal */ false,
+      /*reportToConsole*/ false,
+    );
   } else {
-    console._errorOriginal.apply(console, arguments);
     const stringifySafe = require('../Utilities/stringifySafe');
     const str = Array.prototype.map
       .call(arguments, value =>
@@ -186,7 +236,7 @@ function reactConsoleErrorHandler() {
     }
     const error: ExtendedError = new SyntheticError(str);
     error.name = 'console.error';
-    reportException(error, /* isFatal */ false);
+    reportException(error, /* isFatal */ false, /*reportToConsole*/ false);
   }
 }
 

Libraries/Core/__tests__/ExceptionsManager-test.js

@@ -137,8 +137,9 @@ describe('ExceptionsManager', () => {
           message +
           '\n\n' +
           'This error is located at:' +
-          capturedErrorDefaults.componentStack,
-        // JS engine omitted here!
+          capturedErrorDefaults.componentStack +
+          ', js engine: ' +
+          jsEngine,
       );
     });
 
@@ -293,7 +294,8 @@ describe('ExceptionsManager', () => {
       );
       expect(exceptionData.isFatal).toBe(false);
       expect(mockError.mock.calls[0]).toHaveLength(1);
-      expect(mockError.mock.calls[0][0]).toBe(formattedMessage);
+      expect(mockError.mock.calls[0][0]).toBeInstanceOf(Error);
+      expect(mockError.mock.calls[0][0].toString()).toBe(formattedMessage);
     });
 
     test('logging a string', () => {
@@ -461,6 +463,23 @@ describe('ExceptionsManager', () => {
   });
 
   describe('unstable_setExceptionDecorator', () => {
+    let mockError;
+    beforeEach(() => {
+      // NOTE: We initialise a fresh mock every time using spyOn, above.
+      // We can't use `console._errorOriginal` for this, because that's a bound
+      // (=wrapped) version of the mock and Jest does not approve.
+      mockError = console.error;
+      ExceptionsManager.installConsoleErrorReporter();
+    });
+
+    afterEach(() => {
+      // There is no uninstallConsoleErrorReporter. Do this so the next install
+      // works.
+      console.error = console._errorOriginal;
+      delete console._errorOriginal;
+      delete console.reportErrorsAsExceptions;
+    });
+
     test('modifying the exception data', () => {
       const error = new Error('Some error happened');
       const decorator = jest.fn().mockImplementation(data => ({
@@ -509,7 +528,7 @@ describe('ExceptionsManager', () => {
       expect(nativeReportException).toHaveBeenCalled();
     });
 
-    test('prevents decorator recursion', () => {
+    test('prevents decorator recursion from error handler', () => {
       const error = new Error('Some error happened');
       const decorator = jest.fn().mockImplementation(data => {
         console.error('Logging an error within the decorator');
@@ -519,18 +538,88 @@ describe('ExceptionsManager', () => {
         };
       });
 
-      ExceptionsManager.installConsoleErrorReporter();
       ExceptionsManager.unstable_setExceptionDecorator(decorator);
       ExceptionsManager.handleException(error, true);
 
-      expect(decorator).toHaveBeenCalled();
+      expect(nativeReportException).toHaveBeenCalledTimes(1);
+      expect(nativeReportException.mock.calls[0][0].message).toMatch(
+        /decorated: .*Some error happened/,
+      );
+      expect(mockError).toHaveBeenCalledTimes(2);
+      expect(mockError.mock.calls[0][0]).toMatch(
+        /Logging an error within the decorator/,
+      );
+      expect(mockError.mock.calls[1][0]).toMatch(
+        /decorated: .*Some error happened/,
+      );
+    });
+
+    test('prevents decorator recursion from console.error', () => {
+      const error = new Error('Some error happened');
+      const decorator = jest.fn().mockImplementation(data => {
+        console.error('Logging an error within the decorator');
+        return {
+          ...data,
+          message: 'decorated: ' + data.message,
+        };
+      });
+
+      ExceptionsManager.unstable_setExceptionDecorator(decorator);
+      console.error(error);
+
       expect(nativeReportException).toHaveBeenCalledTimes(2);
       expect(nativeReportException.mock.calls[0][0].message).toMatch(
         /Logging an error within the decorator/,
       );
       expect(nativeReportException.mock.calls[1][0].message).toMatch(
         /decorated: .*Some error happened/,
       );
+      expect(mockError).toHaveBeenCalledTimes(2);
+      // console.error calls are chained without exception pre-processing, so decorator doesn't apply
+      expect(mockError.mock.calls[0][0].toString()).toMatch(
+        /Error: Some error happened/,
+      );
+      expect(mockError.mock.calls[1][0]).toMatch(
+        /Logging an error within the decorator/,
+      );
+    });
+
+    test('can handle throwing decorators recursion when exception is thrown', () => {
+      const error = new Error('Some error happened');
+      const decorator = jest.fn().mockImplementation(data => {
+        throw new Error('Throwing an error within the decorator');
+      });
+
+      ExceptionsManager.unstable_setExceptionDecorator(decorator);
+      ExceptionsManager.handleException(error, true);
+
+      expect(nativeReportException).toHaveBeenCalledTimes(1);
+      // Exceptions in decorators are ignored and the decorator is not applied
+      expect(nativeReportException.mock.calls[0][0].message).toMatch(
+        /Error: Some error happened/,
+      );
+      expect(mockError).toHaveBeenCalledTimes(1);
+      expect(mockError.mock.calls[0][0]).toMatch(/Error: Some error happened/);
+    });
+
+    test('can handle throwing decorators recursion when exception is logged', () => {
+      const error = new Error('Some error happened');
+      const decorator = jest.fn().mockImplementation(data => {
+        throw new Error('Throwing an error within the decorator');
+      });
+
+      ExceptionsManager.unstable_setExceptionDecorator(decorator);
+      console.error(error);
+
+      expect(nativeReportException).toHaveBeenCalledTimes(1);
+      // Exceptions in decorators are ignored and the decorator is not applied
+      expect(nativeReportException.mock.calls[0][0].message).toMatch(
+        /Error: Some error happened/,
+      );
+      expect(mockError).toHaveBeenCalledTimes(1);
+      expect(mockError.mock.calls[0][0].toString()).toMatch(
+        /Error: Some error happened/,
+      );
     });
   });
 });

Libraries/Core/setUpDeveloperTools.js

@@ -54,6 +54,7 @@ if (__DEV__) {
           'trace',
           'info',
           'warn',
+          'error',
           'log',
           'group',
           'groupCollapsed',

Libraries/Utilities/HMRClient.js

@@ -31,6 +31,7 @@ type LogLevel =
   | 'trace'
   | 'info'
   | 'warn'
+  | 'error'
   | 'log'
   | 'group'
   | 'groupCollapsed'