From 851de082bf6ec85c640fc666758df14f18ee2cdf Mon Sep 17 00:00:00 2001 From: Rudolf Meijering Date: Thu, 21 Nov 2019 19:29:27 +0100 Subject: [PATCH 1/5] Retry authentication and other connection failures in migrations --- .../elasticsearch/retry_call_cluster.test.ts | 55 +++++++++++++++++-- .../elasticsearch/retry_call_cluster.ts | 47 ++++++++++++++++ .../saved_objects/saved_objects_service.ts | 4 +- 3 files changed, 99 insertions(+), 7 deletions(-) diff --git a/src/core/server/elasticsearch/retry_call_cluster.test.ts b/src/core/server/elasticsearch/retry_call_cluster.test.ts index 0de10e8fb4f77..b7f70c279ac71 100644 --- a/src/core/server/elasticsearch/retry_call_cluster.test.ts +++ b/src/core/server/elasticsearch/retry_call_cluster.test.ts @@ -18,17 +18,16 @@ */ import * as legacyElasticsearch from 'elasticsearch'; -import { retryCallCluster } from './retry_call_cluster'; +import { retryCallCluster, migrationsRetryCallCluster } from './retry_call_cluster'; describe('retryCallCluster', () => { - it('retries ES API calls that rejects with NoConnection errors', () => { + it('retries ES API calls that rejects with NoConnections', () => { expect.assertions(1); const callEsApi = jest.fn(); let i = 0; + const ErrorConstructor = legacyElasticsearch.errors.NoConnections; callEsApi.mockImplementation(() => { - return i++ <= 2 - ? Promise.reject(new legacyElasticsearch.errors.NoConnections()) - : Promise.resolve('success'); + return i++ <= 2 ? Promise.reject(new ErrorConstructor()) : Promise.resolve('success'); }); const retried = retryCallCluster(callEsApi); return expect(retried('endpoint')).resolves.toMatchInlineSnapshot(`"success"`); @@ -57,3 +56,49 @@ describe('retryCallCluster', () => { return expect(retried('endpoint')).rejects.toMatchInlineSnapshot(`[Error: unknown error]`); }); }); + +describe('migrationsRetryCallCluster', () => { + const errors = [ + 'NoConnections', + 'ConnectionFault', + 'ServiceUnavailable', + 'RequestTimeout', + 'AuthenticationException', + ]; + errors.forEach(errorName => { + it('retries ES API calls that rejects with ' + errorName, () => { + expect.assertions(1); + const callEsApi = jest.fn(); + let i = 0; + const ErrorConstructor = (legacyElasticsearch.errors as any)[errorName]; + callEsApi.mockImplementation(() => { + return i++ <= 2 ? Promise.reject(new ErrorConstructor()) : Promise.resolve('success'); + }); + const retried = migrationsRetryCallCluster(callEsApi); + return expect(retried('endpoint')).resolves.toMatchInlineSnapshot(`"success"`); + }); + }); + + it('rejects when ES API calls reject with other errors', async () => { + expect.assertions(3); + const callEsApi = jest.fn(); + let i = 0; + callEsApi.mockImplementation(() => { + i++; + + return i === 1 + ? Promise.reject(new Error('unknown error')) + : i === 2 + ? Promise.resolve('success') + : i === 3 || i === 4 + ? Promise.reject(new legacyElasticsearch.errors.NoConnections()) + : i === 5 + ? Promise.reject(new Error('unknown error')) + : null; + }); + const retried = migrationsRetryCallCluster(callEsApi); + await expect(retried('endpoint')).rejects.toMatchInlineSnapshot(`[Error: unknown error]`); + await expect(retried('endpoint')).resolves.toMatchInlineSnapshot(`"success"`); + return expect(retried('endpoint')).rejects.toMatchInlineSnapshot(`[Error: unknown error]`); + }); +}); diff --git a/src/core/server/elasticsearch/retry_call_cluster.ts b/src/core/server/elasticsearch/retry_call_cluster.ts index 2e4afa682ea75..3e307270fa9ce 100644 --- a/src/core/server/elasticsearch/retry_call_cluster.ts +++ b/src/core/server/elasticsearch/retry_call_cluster.ts @@ -23,6 +23,53 @@ import * as legacyElasticsearch from 'elasticsearch'; import { CallAPIOptions } from '.'; +const esErrors = legacyElasticsearch.errors; + +/** + * Retries the provided Elasticsearch API call when an error such as + * `AuthenticationException` `NoConnections`, `ConnectionFault`, + * `ServiceUnavailable` or `RequestTimeout` are encountered. The API call will + * be retried once a second, indefinitely, until a successful response or a + * different error is received. + * + * @param apiCaller + */ + +// TODO: Replace with APICaller from './scoped_cluster_client' once #46668 is merged +export function migrationsRetryCallCluster( + apiCaller: ( + endpoint: string, + clientParams: Record, + options?: CallAPIOptions + ) => Promise +) { + return (endpoint: string, clientParams: Record = {}, options?: CallAPIOptions) => { + return defer(() => apiCaller(endpoint, clientParams, options)) + .pipe( + retryWhen(errors => + errors.pipe( + concatMap((error, i) => + iif( + () => { + return ( + error instanceof esErrors.NoConnections || + error instanceof esErrors.ConnectionFault || + error instanceof esErrors.ServiceUnavailable || + error instanceof esErrors.RequestTimeout || + error instanceof esErrors.AuthenticationException + ); + }, + timer(1000), + throwError(error) + ) + ) + ) + ) + ) + .toPromise(); + }; +} + /** * Retries the provided Elasticsearch API call when a `NoConnections` error is * encountered. The API call will be retried once a second, indefinitely, until diff --git a/src/core/server/saved_objects/saved_objects_service.ts b/src/core/server/saved_objects/saved_objects_service.ts index 5ccb02414d043..d7ba6e7b7907d 100644 --- a/src/core/server/saved_objects/saved_objects_service.ts +++ b/src/core/server/saved_objects/saved_objects_service.ts @@ -33,7 +33,7 @@ import { CoreContext } from '../core_context'; import { LegacyServiceSetup } from '../legacy/legacy_service'; import { ElasticsearchServiceSetup } from '../elasticsearch'; import { KibanaConfigType } from '../kibana_config'; -import { retryCallCluster } from '../elasticsearch/retry_call_cluster'; +import { retryCallCluster, migrationsRetryCallCluster } from '../elasticsearch/retry_call_cluster'; import { SavedObjectsConfigType } from './saved_objects_config'; import { KibanaRequest } from '../http'; import { Logger } from '..'; @@ -105,7 +105,7 @@ export class SavedObjectsService config: coreSetup.legacy.pluginExtendedConfig, savedObjectsConfig, kibanaConfig, - callCluster: retryCallCluster(adminClient.callAsInternalUser), + callCluster: migrationsRetryCallCluster(adminClient.callAsInternalUser), })); const mappings = this.migrator.getActiveMappings(); From 9bc54a868dd089e4ec46eea671359263554371a5 Mon Sep 17 00:00:00 2001 From: Rudolf Meijering Date: Thu, 21 Nov 2019 21:11:01 +0100 Subject: [PATCH 2/5] Log migration ES connection errors once, retry every 2.5s --- .../elasticsearch/retry_call_cluster.ts | 23 ++++++++++++------- .../saved_objects/saved_objects_service.ts | 5 +++- 2 files changed, 19 insertions(+), 9 deletions(-) diff --git a/src/core/server/elasticsearch/retry_call_cluster.ts b/src/core/server/elasticsearch/retry_call_cluster.ts index 3e307270fa9ce..2553d26ede051 100644 --- a/src/core/server/elasticsearch/retry_call_cluster.ts +++ b/src/core/server/elasticsearch/retry_call_cluster.ts @@ -22,6 +22,7 @@ import { defer, throwError, iif, timer } from 'rxjs'; import * as legacyElasticsearch from 'elasticsearch'; import { CallAPIOptions } from '.'; +import { Logger } from '../logging'; const esErrors = legacyElasticsearch.errors; @@ -41,15 +42,21 @@ export function migrationsRetryCallCluster( endpoint: string, clientParams: Record, options?: CallAPIOptions - ) => Promise + ) => Promise, + log: Logger ) { + const previousErrors: string[] = []; return (endpoint: string, clientParams: Record = {}, options?: CallAPIOptions) => { return defer(() => apiCaller(endpoint, clientParams, options)) .pipe( - retryWhen(errors => - errors.pipe( - concatMap((error, i) => - iif( + retryWhen(error$ => + error$.pipe( + concatMap((error, i) => { + if (!previousErrors.includes(error.message)) { + log.warn(`Unable to connect to Elasticsearch. Error: ${error.message}`); + previousErrors.push(error.message); + } + return iif( () => { return ( error instanceof esErrors.NoConnections || @@ -59,10 +66,10 @@ export function migrationsRetryCallCluster( error instanceof esErrors.AuthenticationException ); }, - timer(1000), + timer(2500), throwError(error) - ) - ) + ); + }) ) ) ) diff --git a/src/core/server/saved_objects/saved_objects_service.ts b/src/core/server/saved_objects/saved_objects_service.ts index d7ba6e7b7907d..e3437733e7378 100644 --- a/src/core/server/saved_objects/saved_objects_service.ts +++ b/src/core/server/saved_objects/saved_objects_service.ts @@ -105,7 +105,10 @@ export class SavedObjectsService config: coreSetup.legacy.pluginExtendedConfig, savedObjectsConfig, kibanaConfig, - callCluster: migrationsRetryCallCluster(adminClient.callAsInternalUser), + callCluster: migrationsRetryCallCluster( + adminClient.callAsInternalUser, + this.coreContext.logger.get('migrations') + ), })); const mappings = this.migrator.getActiveMappings(); From 7b0df4532363f21e320b51bb62d3d3ff5d4f711b Mon Sep 17 00:00:00 2001 From: Rudolf Meijering Date: Thu, 21 Nov 2019 21:42:37 +0100 Subject: [PATCH 3/5] Test migrations es connection error logging --- .../elasticsearch/retry_call_cluster.test.ts | 32 +++++++++++++++++-- .../elasticsearch/retry_call_cluster.ts | 5 +-- 2 files changed, 33 insertions(+), 4 deletions(-) diff --git a/src/core/server/elasticsearch/retry_call_cluster.test.ts b/src/core/server/elasticsearch/retry_call_cluster.test.ts index b7f70c279ac71..79e75ec919f8e 100644 --- a/src/core/server/elasticsearch/retry_call_cluster.test.ts +++ b/src/core/server/elasticsearch/retry_call_cluster.test.ts @@ -19,6 +19,7 @@ import * as legacyElasticsearch from 'elasticsearch'; import { retryCallCluster, migrationsRetryCallCluster } from './retry_call_cluster'; +import { loggingServiceMock } from '../logging/logging_service.mock'; describe('retryCallCluster', () => { it('retries ES API calls that rejects with NoConnections', () => { @@ -65,6 +66,13 @@ describe('migrationsRetryCallCluster', () => { 'RequestTimeout', 'AuthenticationException', ]; + + const mockLogger = loggingServiceMock.create(); + + beforeEach(() => { + loggingServiceMock.clear(mockLogger); + }); + errors.forEach(errorName => { it('retries ES API calls that rejects with ' + errorName, () => { expect.assertions(1); @@ -74,7 +82,7 @@ describe('migrationsRetryCallCluster', () => { callEsApi.mockImplementation(() => { return i++ <= 2 ? Promise.reject(new ErrorConstructor()) : Promise.resolve('success'); }); - const retried = migrationsRetryCallCluster(callEsApi); + const retried = migrationsRetryCallCluster(callEsApi, mockLogger.get('mock log'), 1); return expect(retried('endpoint')).resolves.toMatchInlineSnapshot(`"success"`); }); }); @@ -96,9 +104,29 @@ describe('migrationsRetryCallCluster', () => { ? Promise.reject(new Error('unknown error')) : null; }); - const retried = migrationsRetryCallCluster(callEsApi); + const retried = migrationsRetryCallCluster(callEsApi, mockLogger.get('mock log'), 1); await expect(retried('endpoint')).rejects.toMatchInlineSnapshot(`[Error: unknown error]`); await expect(retried('endpoint')).resolves.toMatchInlineSnapshot(`"success"`); return expect(retried('endpoint')).rejects.toMatchInlineSnapshot(`[Error: unknown error]`); }); + + it('logs only once for each unique error message', async () => { + const callEsApi = jest.fn(); + callEsApi.mockRejectedValueOnce(new legacyElasticsearch.errors.NoConnections()); + callEsApi.mockRejectedValueOnce(new legacyElasticsearch.errors.NoConnections()); + callEsApi.mockRejectedValueOnce(new legacyElasticsearch.errors.AuthenticationException()); + callEsApi.mockResolvedValueOnce('done'); + const retried = migrationsRetryCallCluster(callEsApi, mockLogger.get('mock log'), 1); + await retried('endpoint'); + expect(loggingServiceMock.collect(mockLogger).warn).toMatchInlineSnapshot(` + Array [ + Array [ + "Unable to connect to Elasticsearch. Error: No Living connections", + ], + Array [ + "Unable to connect to Elasticsearch. Error: Authentication Exception", + ], + ] + `); + }); }); diff --git a/src/core/server/elasticsearch/retry_call_cluster.ts b/src/core/server/elasticsearch/retry_call_cluster.ts index 2553d26ede051..09f21d7b600d2 100644 --- a/src/core/server/elasticsearch/retry_call_cluster.ts +++ b/src/core/server/elasticsearch/retry_call_cluster.ts @@ -43,7 +43,8 @@ export function migrationsRetryCallCluster( clientParams: Record, options?: CallAPIOptions ) => Promise, - log: Logger + log: Logger, + delay: number = 2500 ) { const previousErrors: string[] = []; return (endpoint: string, clientParams: Record = {}, options?: CallAPIOptions) => { @@ -66,7 +67,7 @@ export function migrationsRetryCallCluster( error instanceof esErrors.AuthenticationException ); }, - timer(2500), + timer(delay), throwError(error) ); }) From 592162fd50b36c498f841ca7908a252928ba8b6b Mon Sep 17 00:00:00 2001 From: Rudolf Meijering Date: Thu, 21 Nov 2019 21:43:39 +0100 Subject: [PATCH 4/5] retry on AuthorizationExceptions during migration --- src/core/server/elasticsearch/retry_call_cluster.test.ts | 1 + src/core/server/elasticsearch/retry_call_cluster.ts | 3 ++- 2 files changed, 3 insertions(+), 1 deletion(-) diff --git a/src/core/server/elasticsearch/retry_call_cluster.test.ts b/src/core/server/elasticsearch/retry_call_cluster.test.ts index 79e75ec919f8e..275bda17ab92f 100644 --- a/src/core/server/elasticsearch/retry_call_cluster.test.ts +++ b/src/core/server/elasticsearch/retry_call_cluster.test.ts @@ -65,6 +65,7 @@ describe('migrationsRetryCallCluster', () => { 'ServiceUnavailable', 'RequestTimeout', 'AuthenticationException', + 'AuthorizationException', ]; const mockLogger = loggingServiceMock.create(); diff --git a/src/core/server/elasticsearch/retry_call_cluster.ts b/src/core/server/elasticsearch/retry_call_cluster.ts index 09f21d7b600d2..89d7b88b1675a 100644 --- a/src/core/server/elasticsearch/retry_call_cluster.ts +++ b/src/core/server/elasticsearch/retry_call_cluster.ts @@ -64,7 +64,8 @@ export function migrationsRetryCallCluster( error instanceof esErrors.ConnectionFault || error instanceof esErrors.ServiceUnavailable || error instanceof esErrors.RequestTimeout || - error instanceof esErrors.AuthenticationException + error instanceof esErrors.AuthenticationException || + error instanceof esErrors.AuthorizationException ); }, timer(delay), From 4d189d1b638cae923b2324a02b203edf9d4c1964 Mon Sep 17 00:00:00 2001 From: Josh Dover Date: Thu, 21 Nov 2019 16:27:51 -0600 Subject: [PATCH 5/5] Set delay to 1 for tests --- .../server/saved_objects/saved_objects_service.test.ts | 2 +- src/core/server/saved_objects/saved_objects_service.ts | 8 ++++++-- 2 files changed, 7 insertions(+), 3 deletions(-) diff --git a/src/core/server/saved_objects/saved_objects_service.test.ts b/src/core/server/saved_objects/saved_objects_service.test.ts index 07bb4342c754a..c31ad90011865 100644 --- a/src/core/server/saved_objects/saved_objects_service.test.ts +++ b/src/core/server/saved_objects/saved_objects_service.test.ts @@ -54,7 +54,7 @@ describe('SavedObjectsService', () => { legacy: { uiExports: { savedObjectMappings: [] }, pluginExtendedConfig: {} }, } as unknown) as SavedObjectsSetupDeps; - await soService.setup(coreSetup); + await soService.setup(coreSetup, 1); return expect((KibanaMigrator as jest.Mock).mock.calls[0][0].callCluster()).resolves.toMatch( 'success' diff --git a/src/core/server/saved_objects/saved_objects_service.ts b/src/core/server/saved_objects/saved_objects_service.ts index e3437733e7378..43c3afa3ed639 100644 --- a/src/core/server/saved_objects/saved_objects_service.ts +++ b/src/core/server/saved_objects/saved_objects_service.ts @@ -73,7 +73,10 @@ export class SavedObjectsService this.logger = coreContext.logger.get('savedobjects-service'); } - public async setup(coreSetup: SavedObjectsSetupDeps): Promise { + public async setup( + coreSetup: SavedObjectsSetupDeps, + migrationsRetryDelay?: number + ): Promise { this.logger.debug('Setting up SavedObjects service'); const { @@ -107,7 +110,8 @@ export class SavedObjectsService kibanaConfig, callCluster: migrationsRetryCallCluster( adminClient.callAsInternalUser, - this.coreContext.logger.get('migrations') + this.coreContext.logger.get('migrations'), + migrationsRetryDelay ), }));