improve migration transform failure message and stacktrace (#102478)

* improve migration failure message and stacktrace

* remove console.log

* fix unit tests

* fix integration tests

* fix more unit tests

src/core/server/saved_objects/migrations/core/document_migrator.test.ts

@@ -748,7 +748,8 @@ describe('DocumentMigrator', () => {
         migrator.migrate(_.cloneDeep(failedDoc));
         expect('Did not throw').toEqual('But it should have!');
       } catch (error) {
-        expect(error.message).toBe('Dang diggity!');
+        expect(error.message).toEqual('Migration function for version 1.2.3 threw an error');
+        expect(error.stack.includes(`Caused by:\nError: Dang diggity!`)).toBe(true);
         expect(error).toBeInstanceOf(TransformSavedObjectDocumentError);
       }
     });

src/core/server/saved_objects/migrations/core/document_migrator.ts

@@ -260,6 +260,7 @@ function validateMigrationsMapObject(
       throw new Error(`${prefix} Got ${obj}.`);
     }
   }
+
   function assertValidSemver(version: string, type: string) {
     if (!Semver.valid(version)) {
       throw new Error(
@@ -272,6 +273,7 @@ function validateMigrationsMapObject(
       );
     }
   }
+
   function assertValidTransform(fn: any, version: string, type: string) {
     if (typeof fn !== 'function') {
       throw new Error(`Invalid migration ${type}.${version}: expected a function, but got ${fn}.`);
@@ -680,7 +682,7 @@ function wrapWithTry(
       return { transformedDoc: result, additionalDocs: [] };
     } catch (error) {
       log.error(error);
-      throw new TransformSavedObjectDocumentError(error);
+      throw new TransformSavedObjectDocumentError(error, version);
     }
   };
 }

src/core/server/saved_objects/migrations/core/migrate_raw_docs.test.ts

@@ -233,7 +233,7 @@ describe('migrateRawDocsSafely', () => {
 
   test('instance of Either.left containing transform errors when the transform function throws a TransformSavedObjectDocument error', async () => {
     const transform = jest.fn<any, any>((doc: any) => {
-      throw new TransformSavedObjectDocumentError(new Error('error during transform'));
+      throw new TransformSavedObjectDocumentError(new Error('error during transform'), '8.0.0');
     });
     const task = migrateRawDocsSafely(
       new SavedObjectsSerializer(new SavedObjectTypeRegistry()),
@@ -247,7 +247,7 @@ describe('migrateRawDocsSafely', () => {
     expect(result.left.transformErrors.length).toEqual(1);
     expect(result.left.transformErrors[0]).toMatchInlineSnapshot(`
       Object {
-        "err": [Error: error during transform],
+        "err": [Error: Migration function for version 8.0.0 threw an error],
         "rawId": "a:b",
       }
     `);

src/core/server/saved_objects/migrations/core/transform_saved_object_document_error.test.ts

@@ -10,10 +10,38 @@ import { TransformSavedObjectDocumentError } from './transform_saved_object_docu
 describe('TransformSavedObjectDocumentError', () => {
   it('is a special error', () => {
     const originalError = new Error('Dang diggity!');
-    const err = new TransformSavedObjectDocumentError(originalError);
+    const err = new TransformSavedObjectDocumentError(originalError, '8.0.0');
+
     expect(err).toBeInstanceOf(TransformSavedObjectDocumentError);
     expect(err.stack).not.toBeNull();
     expect(err.originalError).toBe(originalError);
-    expect(err.message).toMatchInlineSnapshot(`"Dang diggity!"`);
+    expect(err.message).toEqual(`Migration function for version 8.0.0 threw an error`);
+  });
+
+  it('adds the stack from the original error', () => {
+    const originalError = new Error('Some went wrong');
+    originalError.stack = 'some stack trace';
+
+    const err = new TransformSavedObjectDocumentError(originalError, '8.0.0');
+    const stackLines = err.stack!.split('\n');
+    const stackLength = stackLines.length;
+
+    expect(stackLength).toBeGreaterThan(3);
+    expect(stackLines[0]).toEqual(`Error: Migration function for version 8.0.0 threw an error`);
+    expect(stackLines[stackLength - 2]).toEqual(`Caused by:`);
+    expect(stackLines[stackLength - 1]).toEqual(`some stack trace`);
+  });
+
+  it('uses the message if the original error does not have a stack', () => {
+    const originalError = new Error('Some went wrong');
+    delete originalError.stack;
+
+    const err = new TransformSavedObjectDocumentError(originalError, '8.0.0');
+    const stackLines = err.stack!.split('\n');
+    const stackLength = stackLines.length;
+
+    expect(stackLength).toBeGreaterThan(3);
+    expect(stackLines[stackLength - 2]).toEqual(`Caused by:`);
+    expect(stackLines[stackLength - 1]).toEqual(`Some went wrong`);
   });
 });

src/core/server/saved_objects/migrations/core/transform_saved_object_document_error.ts

@@ -10,9 +10,13 @@
  * Error thrown when saved object migrations encounter a transformation error.
  * Transformation errors happen when a transform function throws an error for an unsanitized saved object
  */
-
 export class TransformSavedObjectDocumentError extends Error {
-  constructor(public readonly originalError: Error) {
-    super(`${originalError.message}`);
+  constructor(public readonly originalError: Error, public readonly version: string) {
+    super(`Migration function for version ${version} threw an error`);
+    appendCauseStack(this, originalError);
   }
 }
+
+const appendCauseStack = (error: Error, cause: Error) => {
+  error.stack = (error.stack ?? '') + `\nCaused by:\n${cause.stack ?? cause.message}`;
+};

src/core/server/saved_objects/migrationsv2/integration_tests/cleanup.test.ts

@@ -17,6 +17,7 @@ const logFilePath = Path.join(__dirname, 'cleanup_test.log');
 
 const asyncUnlink = Util.promisify(Fs.unlink);
 const asyncReadFile = Util.promisify(Fs.readFile);
+
 async function removeLogFile() {
   // ignore errors if it doesn't exist
   await asyncUnlink(logFilePath).catch(() => void 0);
@@ -99,9 +100,10 @@ describe('migration v2', () => {
     esServer = await startES();
     await root.setup();
 
-    await expect(root.start()).rejects.toThrow(
-      'Unable to complete saved object migrations for the [.kibana] index: Migrations failed. Reason: Corrupt saved object documents: index-pattern:test_index*. To allow migrations to proceed, please delete these documents.'
-    );
+    await expect(root.start()).rejects.toThrowErrorMatchingInlineSnapshot(`
+      "Unable to complete saved object migrations for the [.kibana] index: Migrations failed. Reason: 1 corrupt saved object documents were found: index-pattern:test_index*
+      To allow migrations to proceed, please delete or fix these documents."
+    `);
 
     const logFileContent = await asyncReadFile(logFilePath, 'utf-8');
     const records = logFileContent

src/core/server/saved_objects/migrationsv2/integration_tests/corrupt_outdated_docs.test.ts

@@ -15,6 +15,7 @@ import { Root } from '../../../root';
 const logFilePath = Path.join(__dirname, 'migration_test_corrupt_docs_kibana.log');
 
 const asyncUnlink = Util.promisify(Fs.unlink);
+
 async function removeLogFile() {
   // ignore errors if it doesn't exist
   await asyncUnlink(logFilePath).catch(() => void 0);
@@ -110,11 +111,13 @@ describe('migration v2 with corrupt saved object documents', () => {
       const errorMessage = err.message;
       expect(
         errorMessage.startsWith(
-          'Unable to complete saved object migrations for the [.kibana] index: Migrations failed. Reason: Corrupt saved object documents: '
+          'Unable to complete saved object migrations for the [.kibana] index: Migrations failed. Reason: 19 corrupt saved object documents were found: '
         )
       ).toBeTruthy();
       expect(
-        errorMessage.endsWith(' To allow migrations to proceed, please delete these documents.')
+        errorMessage.endsWith(
+          'To allow migrations to proceed, please delete or fix these documents.'
+        )
       ).toBeTruthy();
       const expectedCorruptDocIds = [
         '"foo:my_name"',

src/core/server/saved_objects/migrationsv2/integration_tests/migration_7_13_0_transform_failures.test.ts

@@ -15,6 +15,7 @@ import { Root } from '../../../root';
 const logFilePath = Path.join(__dirname, '7_13_corrupt_transform_failures_test.log');
 
 const asyncUnlink = Util.promisify(Fs.unlink);
+
 async function removeLogFile() {
   // ignore errors if it doesn't exist
   await asyncUnlink(logFilePath).catch(() => void 0);
@@ -98,11 +99,13 @@ describe('migration v2', () => {
       const errorMessage = err.message;
       expect(
         errorMessage.startsWith(
-          'Unable to complete saved object migrations for the [.kibana] index: Migrations failed. Reason: Corrupt saved object documents: '
+          'Unable to complete saved object migrations for the [.kibana] index: Migrations failed. Reason: 7 corrupt saved object documents were found: '
         )
       ).toBeTruthy();
       expect(
-        errorMessage.endsWith(' To allow migrations to proceed, please delete these documents.')
+        errorMessage.endsWith(
+          'To allow migrations to proceed, please delete or fix these documents.'
+        )
       ).toBeTruthy();
 
       const expectedCorruptDocIds = [
@@ -117,9 +120,13 @@ describe('migration v2', () => {
       for (const corruptDocId of expectedCorruptDocIds) {
         expect(errorMessage.includes(corruptDocId)).toBeTruthy();
       }
-      const expectedTransformErrorMessage =
-        'Transformation errors: space:default: Document "default" has property "space" which belongs to a more recent version of Kibana [6.6.0]. The last known version is [undefined]';
-      expect(errorMessage.includes(expectedTransformErrorMessage)).toBeTruthy();
+
+      expect(errorMessage.includes('7 transformation errors were encountered:')).toBeTruthy();
+      expect(
+        errorMessage.includes(
+          'space:default: Error: Document "default" has property "space" which belongs to a more recent version of Kibana [6.6.0]. The last known version is [undefined]'
+        )
+      ).toBeTruthy();
     }
   });
 });

src/core/server/saved_objects/migrationsv2/integration_tests/type_migration_failure.test.ts

@@ -0,0 +1,201 @@
+/*
+ * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
+ * or more contributor license agreements. Licensed under the Elastic License
+ * 2.0 and the Server Side Public License, v 1; you may not use this file except
+ * in compliance with, at your election, the Elastic License 2.0 or the Server
+ * Side Public License, v 1.
+ */
+
+import Path from 'path';
+import Fs from 'fs';
+import Util from 'util';
+import * as kbnTestServer from '../../../../test_helpers/kbn_server';
+import { Root } from '../../../root';
+
+const logFilePath = Path.join(__dirname, 'migration_test_corrupt_docs_kibana.log');
+
+const asyncUnlink = Util.promisify(Fs.unlink);
+
+async function removeLogFile() {
+  // ignore errors if it doesn't exist
+  await asyncUnlink(logFilePath).catch(() => void 0);
+}
+
+describe('migration v2 with corrupt saved object documents', () => {
+  let esServer: kbnTestServer.TestElasticsearchUtils;
+  let root: Root;
+
+  beforeAll(async () => {
+    await removeLogFile();
+  });
+
+  afterAll(async () => {
+    if (root) {
+      await root.shutdown();
+    }
+    if (esServer) {
+      await esServer.stop();
+    }
+
+    await new Promise((resolve) => setTimeout(resolve, 10000));
+  });
+
+  it('collects corrupt saved object documents accross batches', async () => {
+    const { startES } = kbnTestServer.createTestServers({
+      adjustTimeout: (t: number) => jest.setTimeout(t),
+      settings: {
+        es: {
+          license: 'basic',
+          // contains 4 `foo` objects, all with a `migrationVersion` of `7.13.0`
+          //   - foo:1 and foo:2 have correct values for their `number` property (13 and 42 respectively)
+          //   - foo:3 and foo:4 don't have the property, and will fail during the `7.14.0` registered migration
+          // contains migrated index with 8.0 aliases to skip migration, but run outdated doc search
+          dataArchive: Path.join(__dirname, 'archives', '8.0.0_document_migration_failure.zip'),
+        },
+      },
+    });
+
+    root = createRoot();
+
+    esServer = await startES();
+    const coreSetup = await root.setup();
+
+    coreSetup.savedObjects.registerType({
+      name: 'foo',
+      hidden: false,
+      mappings: {
+        properties: {
+          number: { type: 'integer' },
+        },
+      },
+      namespaceType: 'agnostic',
+      migrations: {
+        '7.14.0': (doc) => {
+          if (doc.attributes.number === undefined) {
+            throw new Error('"number" attribute should be present');
+          }
+          doc.attributes = {
+            ...doc.attributes,
+            number: doc.attributes.number + 9000,
+          };
+          return doc;
+        },
+      },
+    });
+
+    try {
+      await root.start();
+      expect(true).toEqual(false);
+    } catch (err) {
+      const errorMessage = err.message;
+      const errorLines = errorMessage.split('\n');
+
+      expect(errorLines[0]).toEqual(
+        `Unable to complete saved object migrations for the [.kibana] index: Migrations failed. Reason: 2 transformation errors were encountered:`
+      );
+      expect(errorLines[errorLines.length - 1]).toEqual(
+        `To allow migrations to proceed, please delete or fix these documents.`
+      );
+
+      expectMatchOrder(errorLines, [
+        {
+          mode: 'equal',
+          value: '- foo:3: Error: Migration function for version 7.14.0 threw an error',
+        },
+        {
+          mode: 'contain',
+          value: 'at transform',
+        },
+        {
+          mode: 'equal',
+          value: 'Caused by:',
+        },
+        {
+          mode: 'equal',
+          value: 'Error: "number" attribute should be present',
+        },
+        {
+          mode: 'contain',
+          value: 'at migrationFn',
+        },
+        {
+          mode: 'equal',
+          value: '- foo:4: Error: Migration function for version 7.14.0 threw an error',
+        },
+        {
+          mode: 'contain',
+          value: 'at transform',
+        },
+        {
+          mode: 'equal',
+          value: 'Caused by:',
+        },
+        {
+          mode: 'equal',
+          value: 'Error: "number" attribute should be present',
+        },
+        {
+          mode: 'contain',
+          value: 'at migrationFn',
+        },
+      ]);
+    }
+  });
+});
+
+function createRoot() {
+  return kbnTestServer.createRootWithCorePlugins(
+    {
+      migrations: {
+        skip: false,
+        enableV2: true,
+        batchSize: 5,
+      },
+      logging: {
+        appenders: {
+          file: {
+            type: 'file',
+            fileName: logFilePath,
+            layout: {
+              type: 'json',
+            },
+          },
+        },
+        loggers: [
+          {
+            name: 'root',
+            appenders: ['file'],
+          },
+        ],
+      },
+    },
+    {
+      oss: true,
+    }
+  );
+}
+
+type FindInOrderPattern = { mode: 'equal'; value: string } | { mode: 'contain'; value: string };
+
+const expectMatchOrder = (lines: string[], patterns: FindInOrderPattern[]) => {
+  let lineIdx = 0;
+  let patternIdx = 0;
+
+  while (lineIdx < lines.length && patternIdx < patterns.length) {
+    const line = lines[lineIdx];
+    const pattern = patterns[patternIdx];
+    if (lineMatch(line, pattern)) {
+      patternIdx++;
+    }
+    lineIdx++;
+  }
+
+  expect(patternIdx).toEqual(patterns.length);
+};
+
+const lineMatch = (line: string, pattern: FindInOrderPattern) => {
+  if (pattern.mode === 'contain') {
+    return line.trim().includes(pattern.value.trim());
+  }
+  return line.trim() === pattern.value.trim();
+};

src/core/server/saved_objects/migrationsv2/model.test.ts

@@ -863,9 +863,10 @@ describe('migrations v2 model', () => {
         });
         const newState = model(testState, res) as FatalState;
         expect(newState.controlState).toBe('FATAL');
-        expect(newState.reason).toMatchInlineSnapshot(
-          `"Migrations failed. Reason: Corrupt saved object documents: a:b. To allow migrations to proceed, please delete these documents."`
-        );
+        expect(newState.reason).toMatchInlineSnapshot(`
+          "Migrations failed. Reason: 1 corrupt saved object documents were found: a:b
+          To allow migrations to proceed, please delete or fix these documents."
+        `);
         expect(newState.logs).toStrictEqual([]); // No logs because no hits
       });
     });
@@ -1158,7 +1159,10 @@ describe('migrations v2 model', () => {
       it('OUTDATED_DOCUMENTS_SEARCH_READ -> FATAL if no outdated documents to transform and we have failed document migrations', () => {
         const corruptDocumentIdsCarriedOver = ['a:somethingelse'];
         const originalTransformError = new Error('something went wrong');
-        const transFormErr = new TransformSavedObjectDocumentError(originalTransformError);
+        const transFormErr = new TransformSavedObjectDocumentError(
+          originalTransformError,
+          '7.11.0'
+        );
         const transformationErrors = [
           { rawId: 'bob:tail', err: transFormErr },
         ] as TransformErrorObjects[];
@@ -1175,8 +1179,8 @@ describe('migrations v2 model', () => {
         const newState = model(transformErrorsState, res) as FatalState;
         expect(newState.controlState).toBe('FATAL');
         expect(newState.reason.includes('Migrations failed. Reason:')).toBe(true);
-        expect(newState.reason.includes('Corrupt saved object documents: ')).toBe(true);
-        expect(newState.reason.includes('Transformation errors: ')).toBe(true);
+        expect(newState.reason.includes('1 corrupt saved object documents were found')).toBe(true);
+        expect(newState.reason.includes('1 transformation errors were encountered')).toBe(true);
         expect(newState.reason.includes('bob:tail')).toBe(true);
         expect(newState.logs).toStrictEqual([]); // No logs because no hits
       });
@@ -1222,7 +1226,7 @@ describe('migrations v2 model', () => {
       const outdatedDocuments = [{ _id: '1', _source: { type: 'vis' } }];
       const corruptDocumentIds = ['a:somethingelse'];
       const originalTransformError = new Error('Dang diggity!');
-      const transFormErr = new TransformSavedObjectDocumentError(originalTransformError);
+      const transFormErr = new TransformSavedObjectDocumentError(originalTransformError, '7.11.0');
       const transformationErrors = [
         { rawId: 'bob:tail', err: transFormErr },
       ] as TransformErrorObjects[];

src/core/server/saved_objects/migrationsv2/model.ts

@@ -112,17 +112,22 @@ function extractTransformFailuresReason(
 ): string {
   const corruptDocumentIdReason =
     corruptDocumentIds.length > 0
-      ? ` Corrupt saved object documents: ${corruptDocumentIds.join(',')}`
+      ? ` ${
+          corruptDocumentIds.length
+        } corrupt saved object documents were found: ${corruptDocumentIds.join(',')}`
       : '';
   // we have both the saved object Id and the stack trace in each `transformErrors` item.
   const transformErrorsReason =
     transformErrors.length > 0
-      ? ' Transformation errors: ' +
+      ? ` ${transformErrors.length} transformation errors were encountered:\n ` +
         transformErrors
-          .map((errObj) => `${errObj.rawId}: ${errObj.err.message}\n ${errObj.err.stack ?? ''}`)
-          .join('/n')
+          .map((errObj) => `- ${errObj.rawId}: ${errObj.err.stack ?? errObj.err.message}\n`)
+          .join('')
       : '';
-  return `Migrations failed. Reason:${corruptDocumentIdReason}${transformErrorsReason}. To allow migrations to proceed, please delete these documents.`;
+  return (
+    `Migrations failed. Reason:${corruptDocumentIdReason}${transformErrorsReason}\n` +
+    `To allow migrations to proceed, please delete or fix these documents.`
+  );
 }
 
 const delayRetryState = <S extends State>(