Log deprecations originating from Kibana on debug level (#123660) (#123799)

* Log deprecations originating from Kibana on debug level

* Surface debug level deprecation logs on CI

* Review feedback

(cherry picked from commit c64c766444)

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

@@ -540,14 +540,13 @@ describe('instrumentQueryAndDeprecationLogger', () => {
       });
       client.diagnostic.emit('response', new errors.ResponseError(response), response);
 
-      // One debug log entry from 'elasticsearch.query' context
-      expect(loggingSystemMock.collect(logger).debug.length).toEqual(1);
-      expect(loggingSystemMock.collect(logger).info[0][0]).toMatch(
+      // Test debug[1] since theree is one log entry from 'elasticsearch.query' context
+      expect(loggingSystemMock.collect(logger).debug[1][0]).toMatch(
         'Elasticsearch deprecation: 299 Elasticsearch-8.1.0 "GET /_path is deprecated"'
       );
-      expect(loggingSystemMock.collect(logger).info[0][0]).toMatch('Origin:kibana');
-      expect(loggingSystemMock.collect(logger).info[0][0]).toMatch(/Stack trace:\n.*at/);
-      expect(loggingSystemMock.collect(logger).info[0][0]).toMatch(
+      expect(loggingSystemMock.collect(logger).debug[1][0]).toMatch('Origin:kibana');
+      expect(loggingSystemMock.collect(logger).debug[1][0]).toMatch(/Stack trace:\n.*at/);
+      expect(loggingSystemMock.collect(logger).debug[1][0]).toMatch(
         /Query:\n.*400\n.*GET \/_path\?hello\=dolly \[illegal_argument_exception\]: request \[\/_path\] contains unrecognized parameter: \[name\]/
       );
     });
@@ -573,7 +572,6 @@ describe('instrumentQueryAndDeprecationLogger', () => {
       });
       client.diagnostic.emit('response', null, response);
 
-      expect(loggingSystemMock.collect(logger).info).toEqual([]);
       // Test debug[1] since theree is one log entry from 'elasticsearch.query' context
       expect(loggingSystemMock.collect(logger).debug[1][0]).toMatch(
         'Elasticsearch deprecation: 299 Elasticsearch-8.1.0 "GET /_path is deprecated"'
@@ -608,14 +606,13 @@ describe('instrumentQueryAndDeprecationLogger', () => {
       });
       client.diagnostic.emit('response', null, response);
 
-      // One debug log entry from 'elasticsearch.query' context
-      expect(loggingSystemMock.collect(logger).debug.length).toEqual(1);
-      expect(loggingSystemMock.collect(logger).info[0][0]).toMatch(
+      // Test debug[1] since theree is one log entry from 'elasticsearch.query' context
+      expect(loggingSystemMock.collect(logger).debug[1][0]).toMatch(
         'Elasticsearch deprecation: 299 Elasticsearch-8.1.0 "GET /_path is deprecated"'
       );
-      expect(loggingSystemMock.collect(logger).info[0][0]).toMatch('Origin:kibana');
-      expect(loggingSystemMock.collect(logger).info[0][0]).toMatch(/Stack trace:\n.*at/);
-      expect(loggingSystemMock.collect(logger).info[0][0]).toMatch(
+      expect(loggingSystemMock.collect(logger).debug[1][0]).toMatch('Origin:kibana');
+      expect(loggingSystemMock.collect(logger).debug[1][0]).toMatch(/Stack trace:\n.*at/);
+      expect(loggingSystemMock.collect(logger).debug[1][0]).toMatch(
         /Query:\n.*200\n.*GET \/_path\?hello\=dolly/
       );
     });

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

@@ -139,12 +139,9 @@ export const instrumentEsQueryAndDeprecationLogger = ({
         // Strip the first 5 stack trace lines as these are irrelavent to finding the call site
         const stackTrace = new Error().stack?.split('\n').slice(5).join('\n');
 
-        const deprecationMsg = `Elasticsearch deprecation: ${event.warnings}\nOrigin:${requestOrigin}\nStack trace:\n${stackTrace}\nQuery:\n${queryMsg}`;
-        if (requestOrigin === 'kibana') {
-          deprecationLogger.info(deprecationMsg);
-        } else {
-          deprecationLogger.debug(deprecationMsg);
-        }
+        deprecationLogger.debug(
+          `Elasticsearch deprecation: ${event.warnings}\nOrigin:${requestOrigin}\nStack trace:\n${stackTrace}\nQuery:\n${queryMsg}`
+        );
       }
     }
   });

src/core/server/saved_objects/migrations/integration_tests/7.7.2_xpack_100k.test.ts

@@ -63,6 +63,7 @@ describe('migration from 7.7.2-xpack with 100k objects', () => {
           loggers: [
             {
               name: 'root',
+              level: 'info',
               appenders: ['file'],
             },
           ],

src/core/server/saved_objects/migrations/integration_tests/7_13_0_failed_action_tasks.test.ts

@@ -128,6 +128,7 @@ function createRoot() {
         loggers: [
           {
             name: 'root',
+            level: 'info',
             appenders: ['file'],
           },
         ],

src/core/server/saved_objects/migrations/integration_tests/7_13_0_transform_failures.test.ts

@@ -170,6 +170,7 @@ function createRoot() {
         loggers: [
           {
             name: 'root',
+            level: 'info',
             appenders: ['file'],
           },
         ],

src/core/server/saved_objects/migrations/integration_tests/7_13_0_unknown_types.test.ts

@@ -125,6 +125,7 @@ function createRoot() {
         loggers: [
           {
             name: 'root',
+            level: 'info',
             appenders: ['file'],
           },
         ],

src/core/server/saved_objects/migrations/integration_tests/batch_size_bytes.test.ts

@@ -154,6 +154,7 @@ function createRoot(options: { maxBatchSizeBytes?: number }) {
         loggers: [
           {
             name: 'root',
+            level: 'info',
             appenders: ['file'],
           },
         ],

src/core/server/saved_objects/migrations/integration_tests/batch_size_bytes_exceeds_es_content_length.test.ts

@@ -106,6 +106,7 @@ function createRoot(options: { maxBatchSizeBytes?: number }) {
         loggers: [
           {
             name: 'root',
+            level: 'info',
             appenders: ['file'],
           },
         ],

src/core/server/saved_objects/migrations/integration_tests/collects_corrupt_docs.test.ts

@@ -165,6 +165,7 @@ function createRoot() {
           {
             name: 'root',
             appenders: ['file'],
+            level: 'info',
           },
         ],
       },

src/core/server/saved_objects/migrations/integration_tests/corrupt_outdated_docs.test.ts

@@ -169,6 +169,7 @@ function createRoot() {
           {
             name: 'root',
             appenders: ['file'],
+            level: 'info',
           },
         ],
       },

src/core/server/saved_objects/migrations/integration_tests/migration_from_older_v1.test.ts

@@ -94,6 +94,7 @@ describe('migrating from 7.3.0-xpack which used v1 migrations', () => {
             {
               name: 'root',
               appenders: ['file'],
+              level: 'info',
             },
           ],
         },

src/core/server/saved_objects/migrations/integration_tests/migration_from_same_v1.test.ts

@@ -94,6 +94,7 @@ describe('migrating from the same Kibana version that used v1 migrations', () =>
             {
               name: 'root',
               appenders: ['file'],
+              level: 'info',
             },
           ],
         },

src/core/server/saved_objects/migrations/integration_tests/multiple_es_nodes.test.ts

@@ -83,6 +83,7 @@ function createRoot({ logFileName, hosts }: RootConfig) {
         {
           name: 'root',
           appenders: ['file'],
+          level: 'info',
         },
       ],
     },

src/core/server/saved_objects/migrations/integration_tests/multiple_kibana_nodes.test.ts

@@ -83,6 +83,7 @@ async function createRoot({ logFileName }: CreateRootConfig) {
         {
           name: 'root',
           appenders: ['file'],
+          level: 'info',
         },
         {
           name: 'savedobjects-service',

src/core/server/saved_objects/migrations/integration_tests/outdated_docs.test.ts

@@ -109,6 +109,7 @@ function createRoot() {
         loggers: [
           {
             name: 'root',
+            level: 'info',
             appenders: ['file'],
           },
         ],

src/core/server/saved_objects/migrations/integration_tests/rewriting_id.test.ts

@@ -76,6 +76,7 @@ function createRoot() {
         loggers: [
           {
             name: 'root',
+            level: 'info',
             appenders: ['file'],
           },
         ],

src/core/test_helpers/kbn_server.ts

@@ -109,6 +109,25 @@ export function createRootWithCorePlugins(settings = {}, cliArgs: Partial<CliArg
       username: kibanaServerTestUser.username,
       password: kibanaServerTestUser.password,
     },
+    // Log ES deprecations to surface these in CI
+    logging: {
+      loggers: [
+        {
+          name: 'root',
+          level: 'error',
+          appenders: ['console'],
+        },
+        {
+          name: 'elasticsearch.deprecation',
+          level: 'all',
+          appenders: ['deprecation'],
+        },
+      ],
+      appenders: {
+        deprecation: { type: 'console', layout: { type: 'json' } },
+        console: { type: 'console', layout: { type: 'pattern' } },
+      },
+    },
     // createRootWithSettings sets default value to "true", so undefined should be threatened as "true".
     ...(cliArgs.oss === false
       ? {

test/common/config.js

@@ -59,6 +59,7 @@ export default function () {
         '--logging.appenders.deprecation.type=console',
         '--logging.appenders.deprecation.layout.type=json',
         '--logging.loggers[0].name=elasticsearch.deprecation',
+        '--logging.loggers[0].level=all',
         '--logging.loggers[0].appenders[0]=deprecation',
       ],
     },