[test] Surfacing deprecations with rich context from ES warning header

packages/kbn-dev-utils/src/tooling_log/tooling_log_text_writer.ts

@@ -92,7 +92,15 @@ export class ToolingLogTextWriter implements Writer {
     }
 
     if (this.ignoreSources && msg.source && this.ignoreSources.includes(msg.source)) {
-      return false;
+      if (msg.type === 'write') {
+        const txt = format(msg.args[0], ...msg.args.slice(1));
+        // Ensure that Elasticsearch deprecation log messages from Kibana aren't ignored
+        if (!/\[deprecation\]\[elasticsearch\]/.test(txt)) {
+          return false;
+        }
+      } else {
+        return false;
+      }
     }
 
     const prefix = has(MSG_PREFIXES, msg.type) ? MSG_PREFIXES[msg.type] : '';

packages/kbn-pm/dist/index.js

@@ -6639,7 +6639,15 @@ class ToolingLogTextWriter {
     }
 
     if (this.ignoreSources && msg.source && this.ignoreSources.includes(msg.source)) {
-      return false;
+      if (msg.type === 'write') {
+        const txt = (0, _util.format)(msg.args[0], ...msg.args.slice(1)); // Ensure that Elasticsearch deprecation log messages from Kibana aren't ignored
+
+        if (!/\[deprecation\]\[elasticsearch\]/.test(txt)) {
+          return false;
+        }
+      } else {
+        return false;
+      }
     }
 
     const prefix = has(MSG_PREFIXES, msg.type) ? MSG_PREFIXES[msg.type] : '';

src/core/server/elasticsearch/client/configure_client.test.ts

@@ -500,5 +500,152 @@ describe('configureClient', () => {
         `);
       });
     });
+
+    describe('deprecation warnings from response headers', () => {
+      it('does not log when no deprecation warning header is returned', () => {
+        const client = configureClient(createFakeConfig(), { logger, type: 'test', scoped: false });
+
+        const response = createResponseWithBody({
+          seq_no_primary_term: true,
+          query: {
+            term: { user: 'kimchy' },
+          },
+        });
+        client.diagnostic.emit('response', new errors.ResponseError(response), response);
+
+        expect(loggingSystemMock.collect(logger).warn).toEqual([]);
+        expect(loggingSystemMock.collect(logger).error).toEqual([]);
+      });
+
+      it('logs error when the client receives an Elasticsearch error response for a deprecated request originating from a user', () => {
+        const client = configureClient(createFakeConfig(), { logger, type: 'test', scoped: false });
+
+        const response = createApiResponse({
+          statusCode: 400,
+          warnings: ['GET /_path is deprecated'],
+          params: {
+            method: 'GET',
+            path: '/_path',
+            querystring: { hello: 'dolly' },
+          },
+          body: {
+            error: {
+              type: 'illegal_argument_exception',
+              reason: 'request [/_path] contains unrecognized parameter: [name]',
+            },
+          },
+        });
+        client.diagnostic.emit('response', new errors.ResponseError(response), response);
+
+        expect(loggingSystemMock.collect(logger).warn).toEqual([]);
+        expect(loggingSystemMock.collect(logger).error[0][0]).toMatch(
+          'ES DEPRECATION: GET /_path is deprecated'
+        );
+        expect(loggingSystemMock.collect(logger).error[0][0]).toMatch('Origin:user');
+        expect(loggingSystemMock.collect(logger).error[0][0]).toMatch(/Stack trace:\n.*at/);
+        expect(loggingSystemMock.collect(logger).error[0][0]).toMatch(
+          /Query:\n.*400\n.*GET \/_path\?hello\=dolly \[illegal_argument_exception\]: request \[\/_path\] contains unrecognized parameter: \[name\]/
+        );
+      });
+
+      it('logs warning when the client receives an Elasticsearch error response for a deprecated request originating from kibana', () => {
+        const client = configureClient(createFakeConfig(), { logger, type: 'test', scoped: false });
+
+        const response = createApiResponse({
+          statusCode: 400,
+          warnings: ['GET /_path is deprecated'],
+          // Set the request header to indicate to Elasticsearch that this is a request over which users have no control
+          requestOptions: { headers: { 'x-elastic-product-origin': 'kibana' } },
+          params: {
+            method: 'GET',
+            path: '/_path',
+            querystring: { hello: 'dolly' },
+          },
+          body: {
+            error: {
+              type: 'illegal_argument_exception',
+              reason: 'request [/_path] contains unrecognized parameter: [name]',
+            },
+          },
+        });
+        client.diagnostic.emit('response', new errors.ResponseError(response), response);
+
+        expect(loggingSystemMock.collect(logger).error).toEqual([]);
+        expect(loggingSystemMock.collect(logger).warn[0][0]).toMatch(
+          'ES DEPRECATION: GET /_path is deprecated'
+        );
+        expect(loggingSystemMock.collect(logger).warn[0][0]).toMatch('Origin:kibana');
+        expect(loggingSystemMock.collect(logger).warn[0][0]).toMatch(/Stack trace:\n.*at/);
+        expect(loggingSystemMock.collect(logger).warn[0][0]).toMatch(
+          /Query:\n.*400\n.*GET \/_path\?hello\=dolly \[illegal_argument_exception\]: request \[\/_path\] contains unrecognized parameter: \[name\]/
+        );
+      });
+
+      it('logs error when the client receives an Elasticsearch success response for a deprecated request originating from a user', () => {
+        const client = configureClient(createFakeConfig(), { logger, type: 'test', scoped: false });
+
+        const response = createApiResponse({
+          statusCode: 200,
+          warnings: ['GET /_path is deprecated'],
+          params: {
+            method: 'GET',
+            path: '/_path',
+            querystring: { hello: 'dolly' },
+          },
+          body: {
+            hits: [
+              {
+                _source: 'may the source be with you',
+              },
+            ],
+          },
+        });
+        client.diagnostic.emit('response', null, response);
+
+        expect(loggingSystemMock.collect(logger).warn).toEqual([]);
+        expect(loggingSystemMock.collect(logger).error[0][0]).toMatch(
+          'ES DEPRECATION: GET /_path is deprecated'
+        );
+        expect(loggingSystemMock.collect(logger).error[0][0]).toMatch('Origin:user');
+        expect(loggingSystemMock.collect(logger).error[0][0]).toMatch(/Stack trace:\n.*at/);
+        expect(loggingSystemMock.collect(logger).error[0][0]).toMatch(
+          /Query:\n.*200\n.*GET \/_path\?hello\=dolly/
+        );
+      });
+
+      it('logs warning when the client receives an Elasticsearch success response for a deprecated request originating from kibana', () => {
+        const client = configureClient(createFakeConfig(), { logger, type: 'test', scoped: false });
+
+        const response = createApiResponse({
+          statusCode: 200,
+          warnings: ['GET /_path is deprecated'],
+          // Set the request header to indicate to Elasticsearch that this is a request over which users have no control
+          requestOptions: { headers: { 'x-elastic-product-origin': 'kibana' } },
+          params: {
+            method: 'GET',
+            path: '/_path',
+            querystring: { hello: 'dolly' },
+          },
+          body: {
+            hits: [
+              {
+                _source: 'may the source be with you',
+              },
+            ],
+          },
+        });
+        client.diagnostic.emit('response', null, response);
+
+        expect(loggingSystemMock.collect(logger).error).toEqual([]);
+        expect(loggingSystemMock.collect(logger).warn[0][0]).toMatch(
+          'ES DEPRECATION: GET /_path is deprecated'
+        );
+        expect(loggingSystemMock.collect(logger).warn[0][0]).toMatch('Origin:kibana');
+        expect(loggingSystemMock.collect(logger).warn[0][0]).toMatch(/Stack trace:\n.*at/);
+        expect(loggingSystemMock.collect(logger).warn[0][0]).toMatch(
+          /Query:\n.*200\n.*GET \/_path\?hello\=dolly/
+        );
+      });
+    });
   });
 });

src/core/server/elasticsearch/client/configure_client.ts

@@ -14,6 +14,7 @@ import type {
   TransportRequestParams,
   TransportRequestOptions,
 } from '@elastic/elasticsearch/lib/Transport';
+
 import { Logger } from '../../logging';
 import { parseClientOptions, ElasticsearchClientConfig } from './client_config';
 
@@ -47,7 +48,7 @@ export const configureClient = (
   }
 
   const client = new Client({ ...clientOptions, Transport: KibanaTransport });
-  addLogging(client, logger.get('query', type));
+  addLogging({ client, logger, type });
 
   // --------------------------------------------------------------------------------- //
   // Hack to disable the "Product check" only in the scoped clients while we           //
@@ -119,7 +120,9 @@ export function getRequestDebugMeta(event: RequestEvent): {
   };
 }
 
-const addLogging = (client: Client, logger: Logger) => {
+const addLogging = ({ client, type, logger }: { client: Client; type: string; logger: Logger }) => {
+  const queryLogger = logger.get('query', type);
+  const deprecationLogger = logger.get('deprecation');
   client.on('response', (error, event) => {
     if (event) {
       const opaqueId = event.meta.request.options.opaqueId;
@@ -128,14 +131,46 @@ const addLogging = (client: Client, logger: Logger) => {
             http: { request: { id: event.meta.request.options.opaqueId } },
           }
         : undefined; // do not clutter logs if opaqueId is not present
+      let queryMessage = '';
       if (error) {
         if (error instanceof errors.ResponseError) {
-          logger.debug(`${getResponseMessage(event)} ${getErrorMessage(error)}`, meta);
+          queryMessage = `${getResponseMessage(event)} ${getErrorMessage(error)}`;
         } else {
-          logger.debug(getErrorMessage(error), meta);
+          queryMessage = getErrorMessage(error);
         }
       } else {
-        logger.debug(getResponseMessage(event), meta);
+        queryMessage = getResponseMessage(event);
+      }
+
+      queryLogger.debug(queryMessage, meta);
+
+      if (event.warnings && event.warnings.length > 0) {
+        // Plugins can explicitly mark requests as originating from a user by
+        // removing the `'x-elastic-product-origin': 'kibana'` header that's
+        // added by default. User requests will be shown to users in the
+        // upgrade assistant UI as an action item that has to be addressed
+        // before they upgrade.
+        // Kibana requests will be hidden from the upgrade assistant UI and are
+        // only logged to help developers maintain their plugins
+        const requestOrigin =
+          (event.meta.request.options.headers != null &&
+            (event.meta.request.options.headers[
+              'x-elastic-product-origin'
+            ] as unknown as string)) === 'kibana'
+            ? 'kibana'
+            : 'user';
+
+        const stackTrace = new Error().stack?.split('\n').slice(5).join('\n');
+
+        if (requestOrigin === 'kibana') {
+          deprecationLogger.warn(
+            `ES DEPRECATION: ${event.warnings}\nOrigin:${requestOrigin}\nStack trace:\n${stackTrace}\nQuery:\n${queryMessage}`
+          );
+        } else {
+          deprecationLogger.error(
+            `ES DEPRECATION: ${event.warnings}\nOrigin:${requestOrigin}\nStack trace:\n${stackTrace}\nQuery:\n${queryMessage}`
+          );
+        }
       }
     }
   });

src/core/server/logging/logging_config.ts

@@ -65,7 +65,13 @@ export const config = {
       defaultValue: new Map<string, AppenderConfigType>(),
     }),
     loggers: schema.arrayOf(loggerSchema, {
-      defaultValue: [],
+      defaultValue: [
+        {
+          name: 'elasticsearch.deprecation',
+          level: 'off',
+          appenders: [],
+        },
+      ],
     }),
     root: schema.object(
       {

src/core/test_helpers/kbn_server.ts

@@ -105,6 +105,9 @@ export function createRootWithCorePlugins(settings = {}, cliArgs: Partial<CliArg
       username: kibanaServerTestUser.username,
       password: kibanaServerTestUser.password,
     },
+    logging: {
+      loggers: [{ name: 'elasticsearch.deprecation', level: 'all' }],
+    },
     // createRootWithSettings sets default value to "true", so undefined should be threatened as "true".
     ...(cliArgs.oss === false
       ? {

test/common/config.js

@@ -53,6 +53,8 @@ export default function () {
         `--plugin-path=${path.join(__dirname, 'fixtures', 'plugins', 'newsfeed')}`,
         `--newsfeed.service.urlRoot=${servers.kibana.protocol}://${servers.kibana.hostname}:${servers.kibana.port}`,
         `--newsfeed.service.pathTemplate=/api/_newsfeed-FTS-external-service-simulators/kibana/v{VERSION}.json`,
+        '--logging.loggers[0].name=elasticsearch.deprecation',
+        '--logging.loggers[0].level=all',
       ],
     },
     services,