Skip to content

Commit

Permalink
Dump execution log of state transitions and responses if we hit FATAL
Browse files Browse the repository at this point in the history
  • Loading branch information
@rudolf
rudolf committed Dec 9, 2020
1 parent 29cb116 commit a5c92e2
Show file tree
Hide file tree
Showing 4 changed files with 186 additions and 130 deletions.
2 changes: 1 addition & 1 deletion src/core/server/saved_objects/migrations/kibana/kibana_migrator.test.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 () => {
Expand Down
206 changes: 106 additions & 100 deletions src/core/server/saved_objects/migrationsv2/migrations_state_action_machine.test.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -81,127 +81,27 @@ 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 {
"_tag": "Right",
"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 {
"_tag": "Right",
"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 {
"_tag": "Right",
"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 [],
Expand Down Expand Up @@ -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({
Expand Down
104 changes: 76 additions & 28 deletions src/core/server/saved_objects/migrationsv2/migrations_state_action_machine.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -42,40 +93,36 @@ export async function migrationStateActionMachine({
next: Next<State>;
model: Model<State>;
}) {
// 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<State>(
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;
}
);
Expand All @@ -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: ` +
Expand Down
4 changes: 3 additions & 1 deletion src/core/server/saved_objects/migrationsv2/model.test.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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<string>).value).toEqual(
preMigrationScript
);
});
it('returns state without a preMigration script', () => {
expect(
Expand Down

0 comments on commit a5c92e2

Please sign in to comment.