diff --git a/src/core/server/saved_objects/migrations/kibana/kibana_migrator.test.ts b/src/core/server/saved_objects/migrations/kibana/kibana_migrator.test.ts index 4368dbce369760..806258294195de 100644 --- a/src/core/server/saved_objects/migrations/kibana/kibana_migrator.test.ts +++ b/src/core/server/saved_objects/migrations/kibana/kibana_migrator.test.ts @@ -234,7 +234,7 @@ describe('KibanaMigrator', () => { const migrator = new KibanaMigrator(options); return expect(migrator.runMigrations()).rejects.toMatchInlineSnapshot( - `[Error: Unable to complete saved object migrations for the [.my-index] index. The .my-index alias is pointing to a newer version of Kibana: v8.2.4]` + `[Error: Unable to complete saved object migrations for the [.my-index] index: The .my-index alias is pointing to a newer version of Kibana: v8.2.4]` ); }); it('rejects when an unexpected exception occurs in an action', async () => { diff --git a/src/core/server/saved_objects/migrationsv2/migrations_state_action_machine.test.ts b/src/core/server/saved_objects/migrationsv2/migrations_state_action_machine.test.ts index 0a63e270be0366..795c5ca197ac83 100644 --- a/src/core/server/saved_objects/migrationsv2/migrations_state_action_machine.test.ts +++ b/src/core/server/saved_objects/migrationsv2/migrations_state_action_machine.test.ts @@ -81,31 +81,6 @@ describe('migrationsStateActionMachine', () => { "right": "response", }, ], - Array [ - "[.my-so-index] INIT -> LEGACY_REINDEX", - Object { - "controlState": "LEGACY_REINDEX", - "currentAlias": ".my-so-index", - "indexPrefix": ".my-so-index", - "kibanaVersion": "7.11.0", - "legacyIndex": ".my-so-index", - "outdatedDocumentsQuery": Object { - "bool": Object { - "should": Array [], - }, - }, - "preMigrationScript": Object { - "_tag": "None", - }, - "retryCount": 0, - "retryDelay": 0, - "targetMappings": Object { - "properties": Object {}, - }, - "versionAlias": ".my-so-index_7.11.0", - "versionIndex": ".my-so-index_7.11.0_001", - }, - ], Array [ "[.my-so-index] LEGACY_REINDEX RESPONSE", Object { @@ -113,31 +88,6 @@ describe('migrationsStateActionMachine', () => { "right": "response", }, ], - Array [ - "[.my-so-index] LEGACY_REINDEX -> LEGACY_DELETE", - Object { - "controlState": "LEGACY_DELETE", - "currentAlias": ".my-so-index", - "indexPrefix": ".my-so-index", - "kibanaVersion": "7.11.0", - "legacyIndex": ".my-so-index", - "outdatedDocumentsQuery": Object { - "bool": Object { - "should": Array [], - }, - }, - "preMigrationScript": Object { - "_tag": "None", - }, - "retryCount": 0, - "retryDelay": 0, - "targetMappings": Object { - "properties": Object {}, - }, - "versionAlias": ".my-so-index_7.11.0", - "versionIndex": ".my-so-index_7.11.0_001", - }, - ], Array [ "[.my-so-index] LEGACY_DELETE RESPONSE", Object { @@ -145,31 +95,6 @@ describe('migrationsStateActionMachine', () => { "right": "response", }, ], - Array [ - "[.my-so-index] LEGACY_DELETE -> LEGACY_DELETE", - Object { - "controlState": "LEGACY_DELETE", - "currentAlias": ".my-so-index", - "indexPrefix": ".my-so-index", - "kibanaVersion": "7.11.0", - "legacyIndex": ".my-so-index", - "outdatedDocumentsQuery": Object { - "bool": Object { - "should": Array [], - }, - }, - "preMigrationScript": Object { - "_tag": "None", - }, - "retryCount": 0, - "retryDelay": 0, - "targetMappings": Object { - "properties": Object {}, - }, - "versionAlias": ".my-so-index_7.11.0", - "versionIndex": ".my-so-index_7.11.0_001", - }, - ], Array [ "[.my-so-index] LEGACY_DELETE RESPONSE", Object { @@ -177,31 +102,6 @@ describe('migrationsStateActionMachine', () => { "right": "response", }, ], - Array [ - "[.my-so-index] LEGACY_DELETE -> DONE", - Object { - "controlState": "DONE", - "currentAlias": ".my-so-index", - "indexPrefix": ".my-so-index", - "kibanaVersion": "7.11.0", - "legacyIndex": ".my-so-index", - "outdatedDocumentsQuery": Object { - "bool": Object { - "should": Array [], - }, - }, - "preMigrationScript": Object { - "_tag": "None", - }, - "retryCount": 0, - "retryDelay": 0, - "targetMappings": Object { - "properties": Object {}, - }, - "versionAlias": ".my-so-index_7.11.0", - "versionIndex": ".my-so-index_7.11.0_001", - }, - ], ], "error": Array [], "fatal": Array [], @@ -279,6 +179,112 @@ describe('migrationsStateActionMachine', () => { `[Error: Unable to complete saved object migrations for the [.my-so-index] index: the fatal reason]` ); }); + it('logs all state transitions and action responses when reaching the FATAL state', async () => { + await migrationStateActionMachine({ + initialState: { + ...initialState, + reason: 'the fatal reason', + outdatedDocuments: [{ _id: '1234', password: 'sensitive password' }], + } as State, + logger: mockLogger.get(), + model: transitionModel(['LEGACY_DELETE', 'FATAL']), + next, + }).catch((err) => err); + // Ignore the first 4 log entries that come from our model + const executionLogLogs = loggingSystemMock.collect(mockLogger).info.slice(4); + expect(executionLogLogs).toMatchInlineSnapshot(` + Array [ + Array [ + "[.my-so-index] INIT RESPONSE", + Object { + "_tag": "Right", + "right": "response", + }, + ], + Array [ + "[.my-so-index] INIT -> LEGACY_DELETE", + Object { + "controlState": "LEGACY_DELETE", + "currentAlias": ".my-so-index", + "indexPrefix": ".my-so-index", + "kibanaVersion": "7.11.0", + "legacyIndex": ".my-so-index", + "logs": Array [ + Object { + "level": "info", + "message": "Log from LEGACY_DELETE control state", + }, + ], + "outdatedDocuments": Array [ + "1234", + ], + "outdatedDocumentsQuery": Object { + "bool": Object { + "should": Array [], + }, + }, + "preMigrationScript": Object { + "_tag": "None", + }, + "reason": "the fatal reason", + "retryCount": 0, + "retryDelay": 0, + "targetMappings": Object { + "properties": Object {}, + }, + "versionAlias": ".my-so-index_7.11.0", + "versionIndex": ".my-so-index_7.11.0_001", + }, + ], + Array [ + "[.my-so-index] LEGACY_DELETE RESPONSE", + Object { + "_tag": "Right", + "right": "response", + }, + ], + Array [ + "[.my-so-index] LEGACY_DELETE -> FATAL", + Object { + "controlState": "FATAL", + "currentAlias": ".my-so-index", + "indexPrefix": ".my-so-index", + "kibanaVersion": "7.11.0", + "legacyIndex": ".my-so-index", + "logs": Array [ + Object { + "level": "info", + "message": "Log from LEGACY_DELETE control state", + }, + Object { + "level": "info", + "message": "Log from FATAL control state", + }, + ], + "outdatedDocuments": Array [ + "1234", + ], + "outdatedDocumentsQuery": Object { + "bool": Object { + "should": Array [], + }, + }, + "preMigrationScript": Object { + "_tag": "None", + }, + "reason": "the fatal reason", + "retryCount": 0, + "retryDelay": 0, + "targetMappings": Object { + "properties": Object {}, + }, + "versionAlias": ".my-so-index_7.11.0", + "versionIndex": ".my-so-index_7.11.0_001", + }, + ], + ] + `); + }); it('rejects and logs the error when an action throws', async () => { await expect( migrationStateActionMachine({ diff --git a/src/core/server/saved_objects/migrationsv2/migrations_state_action_machine.ts b/src/core/server/saved_objects/migrationsv2/migrations_state_action_machine.ts index b4b054083fdd36..b894f0a6504114 100644 --- a/src/core/server/saved_objects/migrationsv2/migrations_state_action_machine.ts +++ b/src/core/server/saved_objects/migrationsv2/migrations_state_action_machine.ts @@ -22,6 +22,57 @@ import { Logger, LogMeta } from '../../logging'; import { Model, Next, stateActionMachine } from './state_action_machine'; import { State } from './types'; +type ExecutionLog = Array< + | { + type: 'transition'; + prevControlState: State['controlState']; + controlState: State['controlState']; + indexLogMessagePrefix: string; + state: State; + } + | { + type: 'response'; + controlState: State['controlState']; + indexLogMessagePrefix: string; + res: unknown; + } +>; + +// Since saved object index names usually start with a `.` and can be +// configured by users to include several `.`'s we can't use a logger tag to +// indicate which messages come from which index upgrade. +const indexLogMessagePrefix = (state: State) => `[${state.indexPrefix}] `; + +const logStateTransition = (logger: Logger, oldState: State, newState: State) => { + if (newState.logs.length > oldState.logs.length) { + newState.logs + .slice(oldState.logs.length) + .forEach((log) => logger[log.level](indexLogMessagePrefix(newState) + log.message)); + } + + logger.info( + indexLogMessagePrefix(newState) + `${oldState.controlState} -> ${newState.controlState}` + ); +}; + +const logActionResponse = (logger: Logger, state: State, res: unknown) => { + logger.debug(indexLogMessagePrefix(state) + `${state.controlState} RESPONSE`, res as LogMeta); +}; + +const dumpExecutionLog = (logger: Logger, executionLog: ExecutionLog) => { + executionLog.forEach((log) => { + if (log.type === 'transition') { + logger.info( + log.indexLogMessagePrefix + `${log.prevControlState} -> ${log.controlState}`, + log.state + ); + } + if (log.type === 'response') { + logger.info(log.indexLogMessagePrefix + `${log.controlState} RESPONSE`, log.res as LogMeta); + } + }); +}; + /** * A specialized migrations-specific state-action machine that: * - logs messages in state.logs @@ -42,40 +93,36 @@ export async function migrationStateActionMachine({ next: Next; model: Model; }) { - // Since saved object index names usually start with a `.` and can be - // configured by users to include several `.`'s we can't use a logger tag to - // indicate which messages come from which index upgrade. - const indexLogMsgPrefix = `[${initialState.indexPrefix}] `; - const logStateTransition = (oldState: State, newState: State) => { - if (newState.logs.length > oldState.logs.length) { - newState.logs - .slice(oldState.logs.length) - .forEach((log) => logger[log.level](indexLogMsgPrefix + log.message)); - } - - // Redact the state for logging by removing logs and documents which - // might contain sensitive information. - // @ts-expect-error outdatedDocuments don't exist in all states - const { logs, outdatedDocuments, ...redactedState } = newState; - logger.info(indexLogMsgPrefix + `${oldState.controlState} -> ${newState.controlState}`); - logger.debug( - indexLogMsgPrefix + `${oldState.controlState} -> ${newState.controlState}`, - redactedState - ); - }; - - const logActionResponse = (state: State, res: unknown) => { - logger.debug(indexLogMsgPrefix + `${state.controlState} RESPONSE`, res as LogMeta); - }; - + const executionLog: ExecutionLog = []; try { const finalState = await stateActionMachine( initialState, (state) => next(state), (state, res) => { - logActionResponse(state, res); + executionLog.push({ + type: 'response', + res, + indexLogMessagePrefix: indexLogMessagePrefix(state), + controlState: state.controlState, + }); + logActionResponse(logger, state, res); const newState = model(state, res); - logStateTransition(state, newState); + // Redact the state to reduce the memory consumption and so that we + // don't log sensitive information inside documents by only keeping + // the _id's of outdatedDocuments + const redactedNewState = { + ...newState, + // @ts-expect-error outdatedDocuments don't exist in all states + ...{ outdatedDocuments: (newState.outdatedDocuments ?? []).map((doc) => doc._id) }, + }; + executionLog.push({ + type: 'transition', + state: redactedNewState, + controlState: newState.controlState, + prevControlState: state.controlState, + indexLogMessagePrefix: indexLogMessagePrefix(state), + }); + logStateTransition(logger, state, redactedNewState as State); return newState; } ); @@ -96,6 +143,7 @@ export async function migrationStateActionMachine({ }; } } else if (finalState.controlState === 'FATAL') { + dumpExecutionLog(logger, executionLog); return Promise.reject( new Error( `Unable to complete saved object migrations for the [${initialState.indexPrefix}] index: ` + diff --git a/src/core/server/saved_objects/migrationsv2/model.test.ts b/src/core/server/saved_objects/migrationsv2/model.test.ts index 889f8491cd8502..53e5d7f4a98293 100644 --- a/src/core/server/saved_objects/migrationsv2/model.test.ts +++ b/src/core/server/saved_objects/migrationsv2/model.test.ts @@ -869,7 +869,9 @@ describe('migrations v2 model', () => { }); expect(Option.isSome(initialState.preMigrationScript)).toEqual(true); - expect(initialState.preMigrationScript).toEqual(preMigrationScript); + expect((initialState.preMigrationScript as Option.Some).value).toEqual( + preMigrationScript + ); }); it('returns state without a preMigration script', () => { expect(