[HTTP] Log build number mismatch (#170261)

This PR adds new behaviour to log a message when we are not enforcing
strict client-server build number checks and see a different build
number.

## How to test

* Start Kibana
* Set `server.versioned.strictClientVersionCheck: false` in
`kibana.dev.yml`
* Send a request that will return a bad response, in my case I sent
`POST /api/files/files/defaultImage` with an empty body `{}`

## Assumptions

* We only want to log when we are returning a bad response (>=400). It's
possible that we miss events this way, but the assumption is that status
codes >=400 are a strong indication that something is wrong, i.e. we
don't care about mismatches when good responses happen
* We want to treat this as a `WARN` level log
* We will be able to track this in o11y using the `logger` context (like
`kbn-build-number-mismatch`)

## Example

```
[2023-11-02T13:52:48.134+01:00][WARN ][http.kbn-build-number-mismatch] Client build (999999) is older than this Kibana server build (9007199254740991). The [400] error status in req id [29ad1f7c-056a-419b-9051-b45598aebd2c] may be due to client-server incompatibility!
```

packages/core/http/core-http-browser-internal/src/fetch.ts

@@ -23,6 +23,7 @@ import {
   ELASTIC_HTTP_VERSION_HEADER,
   X_ELASTIC_INTERNAL_ORIGIN_REQUEST,
 } from '@kbn/core-http-common';
+import { KIBANA_BUILD_NR_HEADER } from '@kbn/core-http-common';
 import { HttpFetchError } from './http_fetch_error';
 import { HttpInterceptController } from './http_intercept_controller';
 import { interceptRequest, interceptResponse } from './intercept';
@@ -136,7 +137,7 @@ export class Fetch {
         'Content-Type': 'application/json',
         ...options.headers,
         'kbn-version': this.params.kibanaVersion,
-        'kbn-build-number': this.params.buildNumber,
+        [KIBANA_BUILD_NR_HEADER]: this.params.buildNumber,
         [ELASTIC_HTTP_VERSION_HEADER]: version,
         [X_ELASTIC_INTERNAL_ORIGIN_REQUEST]: 'Kibana',
         ...(!isEmpty(context) ? new ExecutionContextContainer(context).toHeader() : {}),

packages/core/http/core-http-common/index.ts

@@ -14,4 +14,5 @@ export {
   ELASTIC_HTTP_VERSION_QUERY_PARAM,
   ELASTIC_INTERNAL_ORIGIN_QUERY_PARAM,
   X_ELASTIC_INTERNAL_ORIGIN_REQUEST,
+  KIBANA_BUILD_NR_HEADER,
 } from './src/constants';

packages/core/http/core-http-common/src/constants.ts

@@ -11,3 +11,6 @@ export const ELASTIC_HTTP_VERSION_HEADER = 'elastic-api-version' as const;
 export const ELASTIC_HTTP_VERSION_QUERY_PARAM = 'apiVersion' as const;
 export const ELASTIC_INTERNAL_ORIGIN_QUERY_PARAM = 'elasticInternalOrigin' as const;
 export const X_ELASTIC_INTERNAL_ORIGIN_REQUEST = 'x-elastic-internal-origin' as const;
+
+/** @internal */
+export const KIBANA_BUILD_NR_HEADER = 'kbn-build-number' as const;

packages/core/http/core-http-server-internal/src/http_service.ts

@@ -102,7 +102,7 @@ export class HttpService
       },
     });
 
-    registerCoreHandlers(prebootSetup, config, this.env);
+    registerCoreHandlers(prebootSetup, config, this.env, this.log);
 
     if (this.shouldListen(config)) {
       this.log.debug('starting preboot server');
@@ -162,7 +162,7 @@ export class HttpService
       deps.executionContext
     );
 
-    registerCoreHandlers(serverContract, config, this.env);
+    registerCoreHandlers(serverContract, config, this.env, this.log);
 
     this.internalSetup = {
       ...serverContract,

packages/core/http/core-http-server-internal/src/lifecycle_handlers.test.ts

@@ -14,9 +14,11 @@ import type {
   OnPostAuthToolkit,
   OnPreRoutingToolkit,
   OnPostAuthHandler,
+  OnPreResponseInfo,
 } from '@kbn/core-http-server';
 import { mockRouter } from '@kbn/core-http-router-server-mocks';
 import {
+  createBuildNrMismatchLoggerPreResponseHandler,
   createCustomHeadersPreResponseHandler,
   createRestrictInternalRoutesPostAuthHandler,
   createVersionCheckPostAuthHandler,
@@ -24,6 +26,9 @@ import {
 } from './lifecycle_handlers';
 
 import { HttpConfig } from './http_config';
+import { loggerMock } from '@kbn/logging-mocks';
+import { Logger } from '@kbn/logging';
+import { KIBANA_BUILD_NR_HEADER } from '@kbn/core-http-common';
 
 type ToolkitMock = jest.Mocked<OnPreResponseToolkit & OnPostAuthToolkit & OnPreRoutingToolkit>;
 
@@ -43,13 +48,18 @@ const forgeRequest = ({
   path = '/',
   method = 'get',
   kibanaRouteOptions,
+  buildNr,
 }: Partial<{
   headers: Record<string, string>;
   query: Record<string, string>;
   path: string;
   method: RouteMethod;
   kibanaRouteOptions: KibanaRouteOptions;
+  buildNr: undefined | string;
 }>): KibanaRequest => {
+  if (buildNr) {
+    headers[KIBANA_BUILD_NR_HEADER] = buildNr;
+  }
   return mockRouter.createKibanaRequest({
     headers,
     path,
@@ -452,3 +462,79 @@ describe('customHeaders pre-response handler', () => {
     });
   });
 });
+
+describe('build number mismatch logger on error pre-response handler', () => {
+  let logger: jest.Mocked<Logger>;
+
+  beforeEach(() => {
+    logger = loggerMock.create();
+  });
+
+  it('injects a logger prefix', () => {
+    createBuildNrMismatchLoggerPreResponseHandler(123, logger);
+    expect(logger.get).toHaveBeenCalledTimes(1);
+    expect(logger.get).toHaveBeenCalledWith(`kbn-build-number-mismatch`);
+  });
+
+  it('does not log for same server-client build', () => {
+    const handler = createBuildNrMismatchLoggerPreResponseHandler(123, logger);
+    const request = forgeRequest({ buildNr: '123' });
+    const response: OnPreResponseInfo = { statusCode: 500 }; // should log for errors, but not this time bc same build nr
+    handler(request, response, createToolkit());
+    expect(logger.warn).not.toHaveBeenCalled();
+  });
+
+  const badStatusCodeTestCases = [
+    /** just test a few common ones */
+    [400],
+    [401],
+    [403],
+    [499],
+    [500],
+    [502],
+    [999] /* and not so common... */,
+  ];
+  it.each(badStatusCodeTestCases)(
+    'logs for %p responses and newer client builds',
+    (responseStatusCode) => {
+      const handler = createBuildNrMismatchLoggerPreResponseHandler(123, logger);
+      const request = forgeRequest({ buildNr: '124' });
+      const response: OnPreResponseInfo = { statusCode: responseStatusCode };
+      handler(request, response, createToolkit());
+      expect(logger.warn).toHaveBeenCalledTimes(1);
+      expect(logger.warn).toHaveBeenCalledWith(
+        `Client build (124) is newer than this Kibana server build (123). The [${responseStatusCode}] error status in req id [123] may be due to client-server incompatibility!`
+      );
+    }
+  );
+
+  it.each(badStatusCodeTestCases)('logs for %p responses and older client builds', (statusCode) => {
+    const handler = createBuildNrMismatchLoggerPreResponseHandler(123, logger);
+    const request = forgeRequest({ buildNr: '122' });
+    const response: OnPreResponseInfo = { statusCode };
+    handler(request, response, createToolkit());
+    expect(logger.warn).toHaveBeenCalledTimes(1);
+    expect(logger.warn).toHaveBeenCalledWith(
+      `Client build (122) is older than this Kibana server build (123). The [${statusCode}] error status in req id [123] may be due to client-server incompatibility!`
+    );
+  });
+
+  it.each([[200], [201], [301], [302]])('does not log for %p responses', (statusCode) => {
+    const handler = createBuildNrMismatchLoggerPreResponseHandler(123, logger);
+    const request = forgeRequest({ buildNr: '124' });
+    const response: OnPreResponseInfo = { statusCode };
+    handler(request, response, createToolkit());
+    expect(logger.warn).not.toHaveBeenCalled();
+  });
+
+  it.each([['foo'], [['yes']], [true], [null], [[]], [undefined]])(
+    'ignores bogus client build numbers like %p',
+    (bogusBuild) => {
+      const handler = createBuildNrMismatchLoggerPreResponseHandler(123, logger);
+      const request = forgeRequest({ buildNr: bogusBuild as any });
+      const response: OnPreResponseInfo = { statusCode: 500 };
+      handler(request, response, createToolkit());
+      expect(logger.warn).not.toHaveBeenCalled();
+    }
+  );
+});

packages/core/http/core-http-server-internal/src/lifecycle_handlers.ts

@@ -6,8 +6,15 @@
  * Side Public License, v 1.
  */
 
-import type { OnPostAuthHandler, OnPreResponseHandler } from '@kbn/core-http-server';
+import type {
+  OnPostAuthHandler,
+  OnPreResponseHandler,
+  OnPreResponseInfo,
+  KibanaRequest,
+} from '@kbn/core-http-server';
 import { isSafeMethod } from '@kbn/core-http-router-server-internal';
+import { Logger } from '@kbn/logging';
+import { KIBANA_BUILD_NR_HEADER } from '@kbn/core-http-common';
 import { HttpConfig } from './http_config';
 
 const VERSION_HEADER = 'kbn-version';
@@ -92,3 +99,44 @@ export const createCustomHeadersPreResponseHandler = (config: HttpConfig): OnPre
     return toolkit.next({ headers: additionalHeaders });
   };
 };
+
+const shouldLogBuildNumberMismatch = (
+  serverBuild: { number: number; string: string },
+  request: KibanaRequest,
+  response: OnPreResponseInfo
+): { log: true; clientBuild: number } | { log: false } => {
+  if (
+    response.statusCode >= 400 &&
+    request.headers[KIBANA_BUILD_NR_HEADER] !== serverBuild.string
+  ) {
+    const clientBuildNumber = parseInt(String(request.headers[KIBANA_BUILD_NR_HEADER]), 10);
+    if (!isNaN(clientBuildNumber)) {
+      return { log: true, clientBuild: clientBuildNumber };
+    }
+  }
+  return { log: false };
+};
+
+/**
+ * This should remain part of the logger prefix so that we can notify/track
+ * when we see this logged for observability purposes.
+ */
+const BUILD_NUMBER_MISMATCH_LOGGER_NAME = 'kbn-build-number-mismatch';
+export const createBuildNrMismatchLoggerPreResponseHandler = (
+  serverBuildNumber: number,
+  log: Logger
+): OnPreResponseHandler => {
+  const serverBuild = { number: serverBuildNumber, string: String(serverBuildNumber) };
+  log = log.get(BUILD_NUMBER_MISMATCH_LOGGER_NAME);
+
+  return (request, response, toolkit) => {
+    const result = shouldLogBuildNumberMismatch(serverBuild, request, response);
+    if (result.log === true) {
+      const clientCompAdjective = result.clientBuild > serverBuildNumber ? 'newer' : 'older';
+      log.warn(
+        `Client build (${result.clientBuild}) is ${clientCompAdjective} than this Kibana server build (${serverBuildNumber}). The [${response.statusCode}] error status in req id [${request.id}] may be due to client-server incompatibility!`
+      );
+    }
+    return toolkit.next();
+  };
+};

packages/core/http/core-http-server-internal/src/register_lifecycle_handlers.test.ts

@@ -11,6 +11,9 @@ jest.mock('./lifecycle_handlers', () => {
   return {
     ...actual,
     createVersionCheckPostAuthHandler: jest.fn(actual.createVersionCheckPostAuthHandler),
+    createBuildNrMismatchLoggerPreResponseHandler: jest.fn(
+      actual.createBuildNrMismatchLoggerPreResponseHandler
+    ),
   };
 });
 
@@ -18,7 +21,11 @@ import { createTestEnv } from '@kbn/config-mocks';
 import type { HttpConfig } from './http_config';
 import { registerCoreHandlers } from './register_lifecycle_handlers';
 
-import { createVersionCheckPostAuthHandler } from './lifecycle_handlers';
+import {
+  createVersionCheckPostAuthHandler,
+  createBuildNrMismatchLoggerPreResponseHandler,
+} from './lifecycle_handlers';
+import { loggerMock } from '@kbn/logging-mocks';
 
 describe('registerCoreHandlers', () => {
   it('will not register client version checking if disabled via config', () => {
@@ -39,11 +46,15 @@ describe('registerCoreHandlers', () => {
       },
     } as unknown as HttpConfig;
 
-    registerCoreHandlers(registrarMock, config, createTestEnv());
+    const logger = loggerMock.create();
+
+    registerCoreHandlers(registrarMock, config, createTestEnv(), logger);
     expect(createVersionCheckPostAuthHandler).toHaveBeenCalledTimes(0);
+    expect(createBuildNrMismatchLoggerPreResponseHandler).toHaveBeenCalledTimes(1); // we do expect to register a logger
 
     config.versioned.strictClientVersionCheck = true;
-    registerCoreHandlers(registrarMock, config, createTestEnv());
+    registerCoreHandlers(registrarMock, config, createTestEnv(), logger);
     expect(createVersionCheckPostAuthHandler).toHaveBeenCalledTimes(1);
+    expect(createBuildNrMismatchLoggerPreResponseHandler).toHaveBeenCalledTimes(1); // logger registration should not be called again
   });
 });

packages/core/http/core-http-server-internal/src/register_lifecycle_handlers.ts

@@ -7,19 +7,22 @@
  */
 
 import type { Env } from '@kbn/config';
+import { Logger } from '@kbn/logging';
 import type { HttpConfig } from './http_config';
 import type { LifecycleRegistrar } from './http_server';
 import {
   createCustomHeadersPreResponseHandler,
   createRestrictInternalRoutesPostAuthHandler,
   createVersionCheckPostAuthHandler,
+  createBuildNrMismatchLoggerPreResponseHandler,
   createXsrfPostAuthHandler,
 } from './lifecycle_handlers';
 
 export const registerCoreHandlers = (
   registrar: LifecycleRegistrar,
   config: HttpConfig,
-  env: Env
+  env: Env,
+  log: Logger
 ) => {
   // add headers based on config
   registrar.registerOnPreResponse(createCustomHeadersPreResponseHandler(config));
@@ -28,6 +31,10 @@ export const registerCoreHandlers = (
   if (config.versioned.strictClientVersionCheck !== false) {
     // add check on version
     registrar.registerOnPostAuth(createVersionCheckPostAuthHandler(env.packageInfo.version));
+  } else {
+    registrar.registerOnPreResponse(
+      createBuildNrMismatchLoggerPreResponseHandler(env.packageInfo.buildNum, log)
+    );
   }
   // add check on header if the route is internal
   registrar.registerOnPostAuth(createRestrictInternalRoutesPostAuthHandler(config)); // strictly speaking, we should have access to route.options.access from the request on postAuth

packages/core/http/core-http-server-mocks/src/test_utils.ts

@@ -107,6 +107,19 @@ export const createCoreContext = (overrides: Partial<CoreContext> = {}): CoreCon
 /**
  * Creates a concrete HttpServer with a mocked context.
  */
-export const createHttpServer = (overrides: Partial<CoreContext> = {}): HttpService => {
-  return new HttpService(createCoreContext(overrides));
+export const createHttpServer = ({
+  buildNum,
+  ...overrides
+}: Partial<CoreContext & { buildNum: number }> = {}): HttpService => {
+  const ctx = createCoreContext(overrides);
+  if (buildNum !== undefined) {
+    ctx.env = {
+      ...ctx.env,
+      packageInfo: {
+        ...ctx.env.packageInfo,
+        buildNum,
+      },
+    };
+  }
+  return new HttpService(ctx);
 };

src/core/server/integration_tests/http/lifecycle_handlers.test.ts

@@ -14,6 +14,10 @@ import { createConfigService, createHttpServer } from '@kbn/core-http-server-moc
 import { HttpService, HttpServerSetup } from '@kbn/core-http-server-internal';
 import { executionContextServiceMock } from '@kbn/core-execution-context-server-mocks';
 import { schema } from '@kbn/config-schema';
+import { IConfigServiceMock } from '@kbn/config-mocks';
+import { Logger } from '@kbn/logging';
+import { loggerMock } from '@kbn/logging-mocks';
+import { KIBANA_BUILD_NR_HEADER } from '@kbn/core-http-common';
 
 const actualVersion = kibanaPackageJson.version;
 const versionHeader = 'kbn-version';
@@ -52,10 +56,12 @@ describe('core lifecycle handlers', () => {
   let server: HttpService;
   let innerServer: HttpServerSetup['server'];
   let router: IRouter;
+  let logger: jest.Mocked<Logger>;
 
   beforeEach(async () => {
     const configService = createConfigService(testConfig);
-    server = createHttpServer({ configService });
+    logger = loggerMock.create();
+    server = createHttpServer({ configService, logger });
     await server.preboot({ context: contextServiceMock.createPrebootContract() });
     const serverSetup = await server.setup(setupDeps);
     router = serverSetup.createRouter('/');
@@ -93,6 +99,14 @@ describe('core lifecycle handlers', () => {
         .set(versionHeader, 'invalid-version')
         .expect(400, /Browser client is out of date/);
     });
+
+    it('does not log a warning message about the build mismatch', async () => {
+      await supertest(innerServer.listener)
+        .get(testRoute)
+        .set(versionHeader, 'invalid-version')
+        .expect(400, /Browser client is out of date/);
+      expect(logger.warn).not.toHaveBeenCalled();
+    });
   });
 
   describe('customHeaders pre-response handler', () => {
@@ -349,13 +363,17 @@ describe('core lifecycle handlers with restrict internal routes enforced', () =>
 });
 
 describe('core lifecycle handlers with no strict client version check', () => {
-  const testRoute = '/version_check/test/route';
+  const testRouteGood = '/no_version_check/test/ok';
+  const testRouteBad = '/no_version_check/test/nok';
   let server: HttpService;
   let innerServer: HttpServerSetup['server'];
   let router: IRouter;
+  let configService: IConfigServiceMock;
+  let logger: jest.Mocked<Logger>;
 
   beforeEach(async () => {
-    const configService = createConfigService({
+    logger = loggerMock.create();
+    configService = createConfigService({
       server: {
         versioned: {
           strictClientVersionCheck: false,
@@ -363,13 +381,16 @@ describe('core lifecycle handlers with no strict client version check', () => {
         },
       },
     });
-    server = createHttpServer({ configService });
+    server = createHttpServer({ configService, logger, buildNum: 1234 });
     await server.preboot({ context: contextServiceMock.createPrebootContract() });
     const serverSetup = await server.setup(setupDeps);
     router = serverSetup.createRouter('/');
-    router.get({ path: testRoute, validate: false }, (context, req, res) => {
+    router.get({ path: testRouteGood, validate: false }, (context, req, res) => {
       return res.ok({ body: 'ok' });
     });
+    router.get({ path: testRouteBad, validate: false }, (context, req, res) => {
+      return res.custom({ body: 'nok', statusCode: 500 });
+    });
     innerServer = serverSetup.server;
     await server.start();
   });
@@ -379,13 +400,38 @@ describe('core lifecycle handlers with no strict client version check', () => {
   });
 
   it('accepts requests that do not include a version header', async () => {
-    await supertest(innerServer.listener).get(testRoute).expect(200, 'ok');
+    await supertest(innerServer.listener).get(testRouteGood).expect(200, 'ok');
   });
 
   it('accepts requests with any version passed in the version header', async () => {
     await supertest(innerServer.listener)
-      .get(testRoute)
+      .get(testRouteGood)
       .set(versionHeader, 'what-have-you')
       .expect(200, 'ok');
   });
+
+  it('logs a warning when a client build number is newer', async () => {
+    await supertest(innerServer.listener)
+      .get(testRouteBad)
+      .set(KIBANA_BUILD_NR_HEADER, '12345')
+      .expect(500, /nok/);
+
+    expect(logger.warn).toHaveBeenCalledTimes(1);
+    const [[message]] = logger.warn.mock.calls;
+    expect(message).toMatch(
+      /^Client build \(12345\) is newer than this Kibana server build \(1234\)/
+    );
+  });
+  it('logs a warning when a client build number is older', async () => {
+    await supertest(innerServer.listener)
+      .get(testRouteBad)
+      .set(KIBANA_BUILD_NR_HEADER, '123')
+      .expect(500, /nok/);
+
+    expect(logger.warn).toHaveBeenCalledTimes(1);
+    const [[message]] = logger.warn.mock.calls;
+    expect(message).toMatch(
+      /^Client build \(123\) is older than this Kibana server build \(1234\)/
+    );
+  });
 });