Remove executionLog to reduce memory consumption (#111911)

Co-authored-by: Kibana Machine <42973632+kibanamachine@users.noreply.github.com>
This commit is contained in:
Rudolf Meijering 2021-09-14 19:20:10 +02:00 committed by GitHub
parent 2262cac584
commit 9b9286fc57
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
6 changed files with 999 additions and 383 deletions

View file

@ -65,8 +65,10 @@ export class FileAppender implements DisposableAppender {
return resolve();
}
this.outputStream.end(() => {
this.outputStream = undefined;
const outputStream = this.outputStream;
this.outputStream = undefined;
outputStream.end(() => {
resolve();
});
});

View file

@ -0,0 +1,937 @@
// Jest Snapshot v1, https://goo.gl/fbAQLP
exports[`migrationsStateActionMachine logs state transitions, messages in state.logs and action responses when reaching DONE 1`] = `
Object {
"debug": Array [
Array [
"[.my-so-index] INIT RESPONSE",
Object {
"_tag": "Right",
"right": "response",
},
],
Array [
"[.my-so-index] INIT -> LEGACY_REINDEX. took: 0ms.",
Object {
"kibana": Object {
"migrations": Object {
"duration": 0,
"state": Object {
"batchSize": 1000,
"controlState": "LEGACY_REINDEX",
"currentAlias": ".my-so-index",
"excludeFromUpgradeFilterHooks": Object {},
"indexPrefix": ".my-so-index",
"kibanaVersion": "7.11.0",
"knownTypes": Array [],
"legacyIndex": ".my-so-index",
"logs": Array [
Object {
"level": "info",
"message": "Log from LEGACY_REINDEX control state",
},
],
"maxBatchSizeBytes": 100000000,
"outdatedDocuments": Array [],
"outdatedDocumentsQuery": Object {
"bool": Object {
"should": Array [],
},
},
"preMigrationScript": Object {
"_tag": "None",
},
"retryAttempts": 5,
"retryCount": 0,
"retryDelay": 0,
"targetIndexMappings": Object {
"properties": Object {},
},
"tempIndex": ".my-so-index_7.11.0_reindex_temp",
"tempIndexMappings": Object {
"dynamic": false,
"properties": Object {
"migrationVersion": Object {
"dynamic": "true",
"type": "object",
},
"type": Object {
"type": "keyword",
},
},
},
"transformedDocBatches": Array [],
"unusedTypesQuery": Object {
"bool": Object {
"must_not": Array [
Object {
"term": Object {
"type": "apm-services-telemetry",
},
},
Object {
"term": Object {
"type": "background-session",
},
},
Object {
"term": Object {
"type": "cases-sub-case",
},
},
Object {
"term": Object {
"type": "file-upload-telemetry",
},
},
Object {
"term": Object {
"type": "fleet-agent-events",
},
},
Object {
"term": Object {
"type": "ml-telemetry",
},
},
Object {
"term": Object {
"type": "osquery-usage-metric",
},
},
Object {
"term": Object {
"type": "server",
},
},
Object {
"term": Object {
"type": "timelion-sheet",
},
},
Object {
"term": Object {
"type": "tsvb-validation-telemetry",
},
},
Object {
"bool": Object {
"must": Array [
Object {
"match": Object {
"type": "search-session",
},
},
Object {
"match": Object {
"search-session.persisted": false,
},
},
],
},
},
],
},
},
"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. took: 0ms.",
Object {
"kibana": Object {
"migrations": Object {
"duration": 0,
"state": Object {
"batchSize": 1000,
"controlState": "LEGACY_DELETE",
"currentAlias": ".my-so-index",
"excludeFromUpgradeFilterHooks": Object {},
"indexPrefix": ".my-so-index",
"kibanaVersion": "7.11.0",
"knownTypes": Array [],
"legacyIndex": ".my-so-index",
"logs": Array [
Object {
"level": "info",
"message": "Log from LEGACY_REINDEX control state",
},
Object {
"level": "info",
"message": "Log from LEGACY_DELETE control state",
},
],
"maxBatchSizeBytes": 100000000,
"outdatedDocuments": Array [],
"outdatedDocumentsQuery": Object {
"bool": Object {
"should": Array [],
},
},
"preMigrationScript": Object {
"_tag": "None",
},
"retryAttempts": 5,
"retryCount": 0,
"retryDelay": 0,
"targetIndexMappings": Object {
"properties": Object {},
},
"tempIndex": ".my-so-index_7.11.0_reindex_temp",
"tempIndexMappings": Object {
"dynamic": false,
"properties": Object {
"migrationVersion": Object {
"dynamic": "true",
"type": "object",
},
"type": Object {
"type": "keyword",
},
},
},
"transformedDocBatches": Array [],
"unusedTypesQuery": Object {
"bool": Object {
"must_not": Array [
Object {
"term": Object {
"type": "apm-services-telemetry",
},
},
Object {
"term": Object {
"type": "background-session",
},
},
Object {
"term": Object {
"type": "cases-sub-case",
},
},
Object {
"term": Object {
"type": "file-upload-telemetry",
},
},
Object {
"term": Object {
"type": "fleet-agent-events",
},
},
Object {
"term": Object {
"type": "ml-telemetry",
},
},
Object {
"term": Object {
"type": "osquery-usage-metric",
},
},
Object {
"term": Object {
"type": "server",
},
},
Object {
"term": Object {
"type": "timelion-sheet",
},
},
Object {
"term": Object {
"type": "tsvb-validation-telemetry",
},
},
Object {
"bool": Object {
"must": Array [
Object {
"match": Object {
"type": "search-session",
},
},
Object {
"match": Object {
"search-session.persisted": false,
},
},
],
},
},
],
},
},
"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. took: 0ms.",
Object {
"kibana": Object {
"migrations": Object {
"duration": 0,
"state": Object {
"batchSize": 1000,
"controlState": "LEGACY_DELETE",
"currentAlias": ".my-so-index",
"excludeFromUpgradeFilterHooks": Object {},
"indexPrefix": ".my-so-index",
"kibanaVersion": "7.11.0",
"knownTypes": Array [],
"legacyIndex": ".my-so-index",
"logs": Array [
Object {
"level": "info",
"message": "Log from LEGACY_REINDEX control state",
},
Object {
"level": "info",
"message": "Log from LEGACY_DELETE control state",
},
Object {
"level": "info",
"message": "Log from LEGACY_DELETE control state",
},
],
"maxBatchSizeBytes": 100000000,
"outdatedDocuments": Array [],
"outdatedDocumentsQuery": Object {
"bool": Object {
"should": Array [],
},
},
"preMigrationScript": Object {
"_tag": "None",
},
"retryAttempts": 5,
"retryCount": 0,
"retryDelay": 0,
"targetIndexMappings": Object {
"properties": Object {},
},
"tempIndex": ".my-so-index_7.11.0_reindex_temp",
"tempIndexMappings": Object {
"dynamic": false,
"properties": Object {
"migrationVersion": Object {
"dynamic": "true",
"type": "object",
},
"type": Object {
"type": "keyword",
},
},
},
"transformedDocBatches": Array [],
"unusedTypesQuery": Object {
"bool": Object {
"must_not": Array [
Object {
"term": Object {
"type": "apm-services-telemetry",
},
},
Object {
"term": Object {
"type": "background-session",
},
},
Object {
"term": Object {
"type": "cases-sub-case",
},
},
Object {
"term": Object {
"type": "file-upload-telemetry",
},
},
Object {
"term": Object {
"type": "fleet-agent-events",
},
},
Object {
"term": Object {
"type": "ml-telemetry",
},
},
Object {
"term": Object {
"type": "osquery-usage-metric",
},
},
Object {
"term": Object {
"type": "server",
},
},
Object {
"term": Object {
"type": "timelion-sheet",
},
},
Object {
"term": Object {
"type": "tsvb-validation-telemetry",
},
},
Object {
"bool": Object {
"must": Array [
Object {
"match": Object {
"type": "search-session",
},
},
Object {
"match": Object {
"search-session.persisted": false,
},
},
],
},
},
],
},
},
"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. took: 0ms.",
Object {
"kibana": Object {
"migrations": Object {
"duration": 0,
"state": Object {
"batchSize": 1000,
"controlState": "DONE",
"currentAlias": ".my-so-index",
"excludeFromUpgradeFilterHooks": Object {},
"indexPrefix": ".my-so-index",
"kibanaVersion": "7.11.0",
"knownTypes": Array [],
"legacyIndex": ".my-so-index",
"logs": Array [
Object {
"level": "info",
"message": "Log from LEGACY_REINDEX control state",
},
Object {
"level": "info",
"message": "Log from LEGACY_DELETE control state",
},
Object {
"level": "info",
"message": "Log from LEGACY_DELETE control state",
},
Object {
"level": "info",
"message": "Log from DONE control state",
},
],
"maxBatchSizeBytes": 100000000,
"outdatedDocuments": Array [],
"outdatedDocumentsQuery": Object {
"bool": Object {
"should": Array [],
},
},
"preMigrationScript": Object {
"_tag": "None",
},
"retryAttempts": 5,
"retryCount": 0,
"retryDelay": 0,
"targetIndexMappings": Object {
"properties": Object {},
},
"tempIndex": ".my-so-index_7.11.0_reindex_temp",
"tempIndexMappings": Object {
"dynamic": false,
"properties": Object {
"migrationVersion": Object {
"dynamic": "true",
"type": "object",
},
"type": Object {
"type": "keyword",
},
},
},
"transformedDocBatches": Array [],
"unusedTypesQuery": Object {
"bool": Object {
"must_not": Array [
Object {
"term": Object {
"type": "apm-services-telemetry",
},
},
Object {
"term": Object {
"type": "background-session",
},
},
Object {
"term": Object {
"type": "cases-sub-case",
},
},
Object {
"term": Object {
"type": "file-upload-telemetry",
},
},
Object {
"term": Object {
"type": "fleet-agent-events",
},
},
Object {
"term": Object {
"type": "ml-telemetry",
},
},
Object {
"term": Object {
"type": "osquery-usage-metric",
},
},
Object {
"term": Object {
"type": "server",
},
},
Object {
"term": Object {
"type": "timelion-sheet",
},
},
Object {
"term": Object {
"type": "tsvb-validation-telemetry",
},
},
Object {
"bool": Object {
"must": Array [
Object {
"match": Object {
"type": "search-session",
},
},
Object {
"match": Object {
"search-session.persisted": false,
},
},
],
},
},
],
},
},
"versionAlias": ".my-so-index_7.11.0",
"versionIndex": ".my-so-index_7.11.0_001",
},
},
},
},
],
],
"error": Array [],
"fatal": Array [],
"info": Array [
Array [
"[.my-so-index] Log from LEGACY_REINDEX control state",
],
Array [
"[.my-so-index] INIT -> LEGACY_REINDEX. took: 0ms.",
],
Array [
"[.my-so-index] Log from LEGACY_DELETE control state",
],
Array [
"[.my-so-index] LEGACY_REINDEX -> LEGACY_DELETE. took: 0ms.",
],
Array [
"[.my-so-index] Log from LEGACY_DELETE control state",
],
Array [
"[.my-so-index] LEGACY_DELETE -> LEGACY_DELETE. took: 0ms.",
],
Array [
"[.my-so-index] Log from DONE control state",
],
Array [
"[.my-so-index] LEGACY_DELETE -> DONE. took: 0ms.",
],
],
"log": Array [],
"trace": Array [],
"warn": Array [],
}
`;
exports[`migrationsStateActionMachine logs state transitions, messages in state.logs and action responses when reaching FATAL 1`] = `
Object {
"debug": Array [
Array [
"[.my-so-index] INIT RESPONSE",
Object {
"_tag": "Right",
"right": "response",
},
],
Array [
"[.my-so-index] INIT -> LEGACY_DELETE. took: 0ms.",
Object {
"kibana": Object {
"migrations": Object {
"duration": 0,
"state": Object {
"batchSize": 1000,
"controlState": "LEGACY_DELETE",
"currentAlias": ".my-so-index",
"excludeFromUpgradeFilterHooks": Object {},
"indexPrefix": ".my-so-index",
"kibanaVersion": "7.11.0",
"knownTypes": Array [],
"legacyIndex": ".my-so-index",
"logs": Array [
Object {
"level": "info",
"message": "Log from LEGACY_DELETE control state",
},
],
"maxBatchSizeBytes": 100000000,
"outdatedDocuments": Array [
Object {
"_id": "1234",
},
],
"outdatedDocumentsQuery": Object {
"bool": Object {
"should": Array [],
},
},
"preMigrationScript": Object {
"_tag": "None",
},
"reason": "the fatal reason",
"retryAttempts": 5,
"retryCount": 0,
"retryDelay": 0,
"targetIndexMappings": Object {
"properties": Object {},
},
"tempIndex": ".my-so-index_7.11.0_reindex_temp",
"tempIndexMappings": Object {
"dynamic": false,
"properties": Object {
"migrationVersion": Object {
"dynamic": "true",
"type": "object",
},
"type": Object {
"type": "keyword",
},
},
},
"transformedDocBatches": Array [
Array [
Object {
"_id": "1234",
},
],
],
"unusedTypesQuery": Object {
"bool": Object {
"must_not": Array [
Object {
"term": Object {
"type": "apm-services-telemetry",
},
},
Object {
"term": Object {
"type": "background-session",
},
},
Object {
"term": Object {
"type": "cases-sub-case",
},
},
Object {
"term": Object {
"type": "file-upload-telemetry",
},
},
Object {
"term": Object {
"type": "fleet-agent-events",
},
},
Object {
"term": Object {
"type": "ml-telemetry",
},
},
Object {
"term": Object {
"type": "osquery-usage-metric",
},
},
Object {
"term": Object {
"type": "server",
},
},
Object {
"term": Object {
"type": "timelion-sheet",
},
},
Object {
"term": Object {
"type": "tsvb-validation-telemetry",
},
},
Object {
"bool": Object {
"must": Array [
Object {
"match": Object {
"type": "search-session",
},
},
Object {
"match": Object {
"search-session.persisted": false,
},
},
],
},
},
],
},
},
"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. took: 0ms.",
Object {
"kibana": Object {
"migrations": Object {
"duration": 0,
"state": Object {
"batchSize": 1000,
"controlState": "FATAL",
"currentAlias": ".my-so-index",
"excludeFromUpgradeFilterHooks": Object {},
"indexPrefix": ".my-so-index",
"kibanaVersion": "7.11.0",
"knownTypes": Array [],
"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",
},
],
"maxBatchSizeBytes": 100000000,
"outdatedDocuments": Array [
Object {
"_id": "1234",
},
],
"outdatedDocumentsQuery": Object {
"bool": Object {
"should": Array [],
},
},
"preMigrationScript": Object {
"_tag": "None",
},
"reason": "the fatal reason",
"retryAttempts": 5,
"retryCount": 0,
"retryDelay": 0,
"targetIndexMappings": Object {
"properties": Object {},
},
"tempIndex": ".my-so-index_7.11.0_reindex_temp",
"tempIndexMappings": Object {
"dynamic": false,
"properties": Object {
"migrationVersion": Object {
"dynamic": "true",
"type": "object",
},
"type": Object {
"type": "keyword",
},
},
},
"transformedDocBatches": Array [
Array [
Object {
"_id": "1234",
},
],
],
"unusedTypesQuery": Object {
"bool": Object {
"must_not": Array [
Object {
"term": Object {
"type": "apm-services-telemetry",
},
},
Object {
"term": Object {
"type": "background-session",
},
},
Object {
"term": Object {
"type": "cases-sub-case",
},
},
Object {
"term": Object {
"type": "file-upload-telemetry",
},
},
Object {
"term": Object {
"type": "fleet-agent-events",
},
},
Object {
"term": Object {
"type": "ml-telemetry",
},
},
Object {
"term": Object {
"type": "osquery-usage-metric",
},
},
Object {
"term": Object {
"type": "server",
},
},
Object {
"term": Object {
"type": "timelion-sheet",
},
},
Object {
"term": Object {
"type": "tsvb-validation-telemetry",
},
},
Object {
"bool": Object {
"must": Array [
Object {
"match": Object {
"type": "search-session",
},
},
Object {
"match": Object {
"search-session.persisted": false,
},
},
],
},
},
],
},
},
"versionAlias": ".my-so-index_7.11.0",
"versionIndex": ".my-so-index_7.11.0_001",
},
},
},
},
],
],
"error": Array [],
"fatal": Array [],
"info": Array [
Array [
"[.my-so-index] Log from LEGACY_DELETE control state",
],
Array [
"[.my-so-index] INIT -> LEGACY_DELETE. took: 0ms.",
],
Array [
"[.my-so-index] Log from FATAL control state",
],
Array [
"[.my-so-index] LEGACY_DELETE -> FATAL. took: 0ms.",
],
],
"log": Array [],
"trace": Array [],
"warn": Array [],
}
`;

View file

@ -44,6 +44,7 @@ function createRoot() {
{
name: 'root',
appenders: ['file'],
level: 'debug', // DEBUG logs are required to retrieve the PIT _id from the action response logs
},
],
},

View file

@ -77,7 +77,7 @@ describe('migrationsStateActionMachine', () => {
};
};
it('logs state transitions, messages in state.logs and action responses', async () => {
it('logs state transitions, messages in state.logs and action responses when reaching DONE', async () => {
await migrationStateActionMachine({
initialState,
logger: mockLogger.get(),
@ -88,71 +88,23 @@ describe('migrationsStateActionMachine', () => {
const logs = loggingSystemMock.collect(mockLogger);
const doneLog = logs.info.splice(8, 1)[0][0];
expect(doneLog).toMatch(/\[.my-so-index\] Migration completed after \d+ms/);
expect(logs).toMatchInlineSnapshot(`
Object {
"debug": Array [
Array [
"[.my-so-index] INIT RESPONSE",
Object {
"_tag": "Right",
"right": "response",
},
],
Array [
"[.my-so-index] LEGACY_REINDEX RESPONSE",
Object {
"_tag": "Right",
"right": "response",
},
],
Array [
"[.my-so-index] LEGACY_DELETE RESPONSE",
Object {
"_tag": "Right",
"right": "response",
},
],
Array [
"[.my-so-index] LEGACY_DELETE RESPONSE",
Object {
"_tag": "Right",
"right": "response",
},
],
],
"error": Array [],
"fatal": Array [],
"info": Array [
Array [
"[.my-so-index] Log from LEGACY_REINDEX control state",
],
Array [
"[.my-so-index] INIT -> LEGACY_REINDEX. took: 0ms.",
],
Array [
"[.my-so-index] Log from LEGACY_DELETE control state",
],
Array [
"[.my-so-index] LEGACY_REINDEX -> LEGACY_DELETE. took: 0ms.",
],
Array [
"[.my-so-index] Log from LEGACY_DELETE control state",
],
Array [
"[.my-so-index] LEGACY_DELETE -> LEGACY_DELETE. took: 0ms.",
],
Array [
"[.my-so-index] Log from DONE control state",
],
Array [
"[.my-so-index] LEGACY_DELETE -> DONE. took: 0ms.",
],
],
"log": Array [],
"trace": Array [],
"warn": Array [],
}
`);
expect(logs).toMatchSnapshot();
});
it('logs state transitions, messages in state.logs and action responses when reaching FATAL', async () => {
await migrationStateActionMachine({
initialState: {
...initialState,
reason: 'the fatal reason',
outdatedDocuments: [{ _id: '1234', password: 'sensitive password' }],
transformedDocBatches: [[{ _id: '1234', password: 'sensitive transformed password' }]],
} as State,
logger: mockLogger.get(),
model: transitionModel(['LEGACY_DELETE', 'FATAL']),
next,
client: esClient,
}).catch((err) => err);
expect(loggingSystemMock.collect(mockLogger)).toMatchSnapshot();
});
// see https://github.com/elastic/kibana/issues/98406
@ -196,6 +148,7 @@ describe('migrationsStateActionMachine', () => {
})
).resolves.toEqual(expect.anything());
});
it('resolves with migrated status if some sourceIndex in the DONE state', async () => {
await expect(
migrationStateActionMachine({
@ -207,6 +160,7 @@ describe('migrationsStateActionMachine', () => {
})
).resolves.toEqual(expect.objectContaining({ status: 'migrated' }));
});
it('resolves with patched status if none sourceIndex in the DONE state', async () => {
await expect(
migrationStateActionMachine({
@ -218,6 +172,7 @@ describe('migrationsStateActionMachine', () => {
})
).resolves.toEqual(expect.objectContaining({ status: 'patched' }));
});
it('rejects with error message when reaching the FATAL state', async () => {
await expect(
migrationStateActionMachine({
@ -231,127 +186,8 @@ 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' }],
transformedDocBatches: [[{ _id: '1234', password: 'sensitive transformed password' }]],
} as State,
logger: mockLogger.get(),
model: transitionModel(['LEGACY_DELETE', 'FATAL']),
next,
client: esClient,
}).catch((err) => err);
// Ignore the first 4 log entries that come from our model
const executionLogLogs = loggingSystemMock.collect(mockLogger).info.slice(4);
expect(executionLogLogs).toEqual([
[
'[.my-so-index] INIT RESPONSE',
{
_tag: 'Right',
right: 'response',
},
],
[
'[.my-so-index] INIT -> LEGACY_DELETE',
{
kibana: {
migrationState: {
batchSize: 1000,
maxBatchSizeBytes: 1e8,
controlState: 'LEGACY_DELETE',
currentAlias: '.my-so-index',
excludeFromUpgradeFilterHooks: {},
indexPrefix: '.my-so-index',
kibanaVersion: '7.11.0',
knownTypes: [],
legacyIndex: '.my-so-index',
logs: [
{
level: 'info',
message: 'Log from LEGACY_DELETE control state',
},
],
outdatedDocuments: [{ _id: '1234' }],
outdatedDocumentsQuery: expect.any(Object),
preMigrationScript: {
_tag: 'None',
},
reason: 'the fatal reason',
retryAttempts: 5,
retryCount: 0,
retryDelay: 0,
targetIndexMappings: {
properties: {},
},
tempIndex: '.my-so-index_7.11.0_reindex_temp',
tempIndexMappings: expect.any(Object),
transformedDocBatches: [[{ _id: '1234' }]],
unusedTypesQuery: expect.any(Object),
versionAlias: '.my-so-index_7.11.0',
versionIndex: '.my-so-index_7.11.0_001',
},
},
},
],
[
'[.my-so-index] LEGACY_DELETE RESPONSE',
{
_tag: 'Right',
right: 'response',
},
],
[
'[.my-so-index] LEGACY_DELETE -> FATAL',
{
kibana: {
migrationState: {
batchSize: 1000,
maxBatchSizeBytes: 1e8,
controlState: 'FATAL',
currentAlias: '.my-so-index',
excludeFromUpgradeFilterHooks: {},
indexPrefix: '.my-so-index',
kibanaVersion: '7.11.0',
knownTypes: [],
legacyIndex: '.my-so-index',
logs: [
{
level: 'info',
message: 'Log from LEGACY_DELETE control state',
},
{
level: 'info',
message: 'Log from FATAL control state',
},
],
outdatedDocuments: [{ _id: '1234' }],
outdatedDocumentsQuery: expect.any(Object),
preMigrationScript: {
_tag: 'None',
},
reason: 'the fatal reason',
retryAttempts: 5,
retryCount: 0,
retryDelay: 0,
targetIndexMappings: {
properties: {},
},
tempIndex: '.my-so-index_7.11.0_reindex_temp',
tempIndexMappings: expect.any(Object),
transformedDocBatches: [[{ _id: '1234' }]],
unusedTypesQuery: expect.any(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 with an ResponseError', async () => {
it('rejects and logs the error when an action throws with a ResponseError', async () => {
await expect(
migrationStateActionMachine({
initialState: { ...initialState, reason: 'the fatal reason' } as State,
@ -384,9 +220,6 @@ describe('migrationsStateActionMachine', () => {
Array [
"[.my-so-index] Unexpected Elasticsearch ResponseError: statusCode: 200, method: POST, url: /mock error: [snapshot_in_progress_exception]: Cannot delete indices that are being snapshotted,",
],
Array [
"[.my-so-index] migration failed, dumping execution log:",
],
],
"fatal": Array [],
"info": Array [],
@ -417,9 +250,6 @@ describe('migrationsStateActionMachine', () => {
Array [
[Error: this action throws],
],
Array [
"[.my-so-index] migration failed, dumping execution log:",
],
],
"fatal": Array [],
"info": Array [],
@ -429,116 +259,6 @@ describe('migrationsStateActionMachine', () => {
}
`);
});
it('logs all state transitions and action responses when an action throws', async () => {
try {
await migrationStateActionMachine({
initialState: { ...initialState, reason: 'the fatal reason' } as State,
logger: mockLogger.get(),
model: transitionModel(['LEGACY_REINDEX', 'LEGACY_DELETE', 'FATAL']),
next: (state) => {
if (state.controlState === 'LEGACY_DELETE') throw new Error('this action throws');
return () => Promise.resolve('hello');
},
client: esClient,
});
} catch (e) {
/** ignore */
}
// Ignore the first 4 log entries that come from our model
const executionLogLogs = loggingSystemMock.collect(mockLogger).info.slice(4);
expect(executionLogLogs).toEqual([
['[.my-so-index] INIT RESPONSE', 'hello'],
[
'[.my-so-index] INIT -> LEGACY_REINDEX',
{
kibana: {
migrationState: {
batchSize: 1000,
maxBatchSizeBytes: 1e8,
controlState: 'LEGACY_REINDEX',
currentAlias: '.my-so-index',
excludeFromUpgradeFilterHooks: {},
indexPrefix: '.my-so-index',
kibanaVersion: '7.11.0',
knownTypes: [],
legacyIndex: '.my-so-index',
logs: [
{
level: 'info',
message: 'Log from LEGACY_REINDEX control state',
},
],
outdatedDocuments: [],
outdatedDocumentsQuery: expect.any(Object),
preMigrationScript: {
_tag: 'None',
},
reason: 'the fatal reason',
retryAttempts: 5,
retryCount: 0,
retryDelay: 0,
targetIndexMappings: {
properties: {},
},
tempIndex: '.my-so-index_7.11.0_reindex_temp',
tempIndexMappings: expect.any(Object),
transformedDocBatches: [],
unusedTypesQuery: expect.any(Object),
versionAlias: '.my-so-index_7.11.0',
versionIndex: '.my-so-index_7.11.0_001',
},
},
},
],
['[.my-so-index] LEGACY_REINDEX RESPONSE', 'hello'],
[
'[.my-so-index] LEGACY_REINDEX -> LEGACY_DELETE',
{
kibana: {
migrationState: {
batchSize: 1000,
maxBatchSizeBytes: 1e8,
controlState: 'LEGACY_DELETE',
currentAlias: '.my-so-index',
excludeFromUpgradeFilterHooks: {},
indexPrefix: '.my-so-index',
kibanaVersion: '7.11.0',
knownTypes: [],
legacyIndex: '.my-so-index',
logs: [
{
level: 'info',
message: 'Log from LEGACY_REINDEX control state',
},
{
level: 'info',
message: 'Log from LEGACY_DELETE control state',
},
],
outdatedDocuments: [],
outdatedDocumentsQuery: expect.any(Object),
preMigrationScript: {
_tag: 'None',
},
reason: 'the fatal reason',
retryAttempts: 5,
retryCount: 0,
retryDelay: 0,
targetIndexMappings: {
properties: {},
},
tempIndex: '.my-so-index_7.11.0_reindex_temp',
tempIndexMappings: expect.any(Object),
transformedDocBatches: [],
unusedTypesQuery: expect.any(Object),
versionAlias: '.my-so-index_7.11.0',
versionIndex: '.my-so-index_7.11.0_001',
},
},
},
],
]);
});
describe('cleanup', () => {
beforeEach(() => {
cleanupMock.mockClear();

View file

@ -16,41 +16,24 @@ import { cleanup } from './migrations_state_machine_cleanup';
import { ReindexSourceToTempIndex, ReindexSourceToTempIndexBulk, State } from './types';
import { SavedObjectsRawDoc } from '../serialization';
interface StateLogMeta extends LogMeta {
interface StateTransitionLogMeta extends LogMeta {
kibana: {
migrationState: State;
migrations: {
state: State;
duration: number;
};
};
}
/** @internal */
export type ExecutionLog = Array<
| {
type: 'transition';
prevControlState: State['controlState'];
controlState: State['controlState'];
state: State;
}
| {
type: 'response';
controlState: State['controlState'];
res: unknown;
}
| {
type: 'cleanup';
state: State;
message: string;
}
>;
const logStateTransition = (
logger: Logger,
logMessagePrefix: string,
oldState: State,
newState: State,
prevState: State,
currState: State,
tookMs: number
) => {
if (newState.logs.length > oldState.logs.length) {
newState.logs.slice(oldState.logs.length).forEach(({ message, level }) => {
if (currState.logs.length > prevState.logs.length) {
currState.logs.slice(prevState.logs.length).forEach(({ message, level }) => {
switch (level) {
case 'error':
return logger.error(logMessagePrefix + message);
@ -65,7 +48,18 @@ const logStateTransition = (
}
logger.info(
logMessagePrefix + `${oldState.controlState} -> ${newState.controlState}. took: ${tookMs}ms.`
logMessagePrefix + `${prevState.controlState} -> ${currState.controlState}. took: ${tookMs}ms.`
);
logger.debug<StateTransitionLogMeta>(
logMessagePrefix + `${prevState.controlState} -> ${currState.controlState}. took: ${tookMs}ms.`,
{
kibana: {
migrations: {
state: currState,
duration: tookMs,
},
},
}
);
};
@ -77,24 +71,6 @@ const logActionResponse = (
) => {
logger.debug(logMessagePrefix + `${state.controlState} RESPONSE`, res as LogMeta);
};
const dumpExecutionLog = (logger: Logger, logMessagePrefix: string, executionLog: ExecutionLog) => {
logger.error(logMessagePrefix + 'migration failed, dumping execution log:');
executionLog.forEach((log) => {
if (log.type === 'transition') {
logger.info<StateLogMeta>(
logMessagePrefix + `${log.prevControlState} -> ${log.controlState}`,
{
kibana: {
migrationState: log.state,
},
}
);
}
if (log.type === 'response') {
logger.info(logMessagePrefix + `${log.controlState} RESPONSE`, log.res as LogMeta);
}
});
};
/**
* A specialized migrations-specific state-action machine that:
@ -118,7 +94,6 @@ export async function migrationStateActionMachine({
model: Model<State>;
client: ElasticsearchClient;
}) {
const executionLog: ExecutionLog = [];
const startTime = Date.now();
// 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
@ -132,11 +107,6 @@ export async function migrationStateActionMachine({
(state) => next(state),
(state, res) => {
lastState = state;
executionLog.push({
type: 'response',
res,
controlState: state.controlState,
});
logActionResponse(logger, logMessagePrefix, state, res);
const newState = model(state, res);
// Redact the state to reduce the memory consumption and so that we
@ -158,12 +128,7 @@ export async function migrationStateActionMachine({
).map((batches) => batches.map((doc) => ({ _id: doc._id }))) as [SavedObjectsRawDoc[]],
},
};
executionLog.push({
type: 'transition',
state: redactedNewState,
controlState: newState.controlState,
prevControlState: state.controlState,
});
const now = Date.now();
logStateTransition(
logger,
@ -195,8 +160,11 @@ export async function migrationStateActionMachine({
};
}
} else if (finalState.controlState === 'FATAL') {
await cleanup(client, executionLog, finalState);
dumpExecutionLog(logger, logMessagePrefix, executionLog);
try {
await cleanup(client, finalState);
} catch (e) {
logger.warn('Failed to cleanup after migrations:', e.message);
}
return Promise.reject(
new Error(
`Unable to complete saved object migrations for the [${initialState.indexPrefix}] index: ` +
@ -207,7 +175,11 @@ export async function migrationStateActionMachine({
throw new Error('Invalid terminating control state');
}
} catch (e) {
await cleanup(client, executionLog, lastState);
try {
await cleanup(client, lastState);
} catch (err) {
logger.warn('Failed to cleanup after migrations:', err.message);
}
if (e instanceof EsErrors.ResponseError) {
// Log the failed request. This is very similar to the
// elasticsearch-service's debug logs, but we log everything in single
@ -219,15 +191,12 @@ export async function migrationStateActionMachine({
req.statusCode
}, method: ${req.method}, url: ${req.url} error: ${getErrorMessage(e)},`;
logger.error(logMessagePrefix + failedRequestMessage);
dumpExecutionLog(logger, logMessagePrefix, executionLog);
throw new Error(
`Unable to complete saved object migrations for the [${initialState.indexPrefix}] index. Please check the health of your Elasticsearch cluster and try again. ${failedRequestMessage}`
);
} else {
logger.error(e);
dumpExecutionLog(logger, logMessagePrefix, executionLog);
const newError = new Error(
`Unable to complete saved object migrations for the [${initialState.indexPrefix}] index. ${e}`
);

View file

@ -9,23 +9,10 @@
import type { ElasticsearchClient } from '../../elasticsearch';
import * as Actions from './actions';
import type { State } from './types';
import type { ExecutionLog } from './migrations_state_action_machine';
export async function cleanup(
client: ElasticsearchClient,
executionLog: ExecutionLog,
state?: State
) {
export async function cleanup(client: ElasticsearchClient, state?: State) {
if (!state) return;
if ('sourceIndexPitId' in state) {
try {
await Actions.closePit({ client, pitId: state.sourceIndexPitId })();
} catch (e) {
executionLog.push({
type: 'cleanup',
state,
message: e.message,
});
}
await Actions.closePit({ client, pitId: state.sourceIndexPitId })();
}
}