Improve security plugin logging. (elastic#176503)

## Summary

Improve security plugin logging:

* [x] If authorization fails with `403` and the user doesn't have any
roles, we can log this valuable information directly in the log.
Similarly, when authentication fails because of `500`, we should
indicate in the logs that the cluster might not be healthy, and so on.
* [x] If Kibana has to create a new session while another one is still
active (e.g., in the case of repeated IdP-initiated login), we should
log this with an `INFO` level, as it's not something ordinary.
* [x] We should reword infamous `License is not available,
authentication is not possible.` message to indicate the underlying
reason in a clearer manner (e.g., ES isn't available etc.).
* [x] We should consider bumping log level to `INFO` for anything else
that would be helpful during debugging
* [x] We shouldn't log `Session is no longer available and cannot be
re-authenticated` (or downgrade it to `DEBUG`) if re-authentication
isn't possible in principle (e.g. in case of HTTP authentication, API
keys, and JWTs)

__Fixes: https://github.com/elastic/kibana/issues/163045__

x-pack/packages/security/plugin_types_common/src/licensing/license.ts

@@ -13,6 +13,7 @@ import type { SecurityLicenseFeatures } from './license_features';
 
 export interface SecurityLicense {
   isLicenseAvailable(): boolean;
+  getUnavailableReason: () => string | undefined;
   isEnabled(): boolean;
   getFeatures(): SecurityLicenseFeatures;
   hasAtLeast(licenseType: LicenseType): boolean | undefined;

x-pack/plugins/security/common/licensing/index.mock.ts

@@ -17,6 +17,7 @@ export const licenseMock = {
     licenseType: LicenseType = 'basic' // default to basic if this is not specified
   ): jest.Mocked<SecurityLicense> => ({
     isLicenseAvailable: jest.fn().mockReturnValue(true),
+    getUnavailableReason: jest.fn(),
     isEnabled: jest.fn().mockReturnValue(true),
     getFeatures: jest.fn().mockReturnValue(features),
     hasAtLeast: jest

x-pack/plugins/security/common/licensing/license_service.ts

@@ -28,6 +28,8 @@ export class SecurityLicenseService {
       license: Object.freeze({
         isLicenseAvailable: () => rawLicense?.isAvailable ?? false,
 
+        getUnavailableReason: () => rawLicense?.getUnavailableReason(),
+
         isEnabled: () => this.isSecurityEnabledFromRawLicense(rawLicense),
 
         hasAtLeast: (licenseType: LicenseType) => rawLicense?.hasAtLeast(licenseType),

x-pack/plugins/security/public/plugin.test.tsx

@@ -39,6 +39,7 @@ describe('Security Plugin', () => {
         license: {
           isLicenseAvailable: expect.any(Function),
           isEnabled: expect.any(Function),
+          getUnavailableReason: expect.any(Function),
           getFeatures: expect.any(Function),
           hasAtLeast: expect.any(Function),
           features$: expect.any(Observable),
@@ -66,6 +67,7 @@ describe('Security Plugin', () => {
         license: {
           isLicenseAvailable: expect.any(Function),
           isEnabled: expect.any(Function),
+          getUnavailableReason: expect.any(Function),
           getFeatures: expect.any(Function),
           hasAtLeast: expect.any(Function),
           features$: expect.any(Observable),

x-pack/plugins/security/server/authentication/authentication_service.test.ts

@@ -206,7 +206,7 @@ describe('AuthenticationService', () => {
 
         expect(mockResponse.customError).toHaveBeenCalledTimes(1);
         expect(mockResponse.customError).toHaveBeenCalledWith({
-          body: 'License is not available.',
+          body: 'License information could not be obtained from Elasticsearch. Please check the logs for further details.',
           statusCode: 503,
           headers: { 'Retry-After': '30' },
         });

x-pack/plugins/security/server/authentication/authentication_service.ts

@@ -112,9 +112,13 @@ export class AuthenticationService {
 
     http.registerAuth(async (request, response, t) => {
       if (!license.isLicenseAvailable()) {
-        this.logger.error('License is not available, authentication is not possible.');
+        this.logger.error(
+          `License information could not be obtained from Elasticsearch due to an error: ${
+            license.getUnavailableReason() ?? 'unknown'
+          }`
+        );
         return response.customError({
-          body: 'License is not available.',
+          body: 'License information could not be obtained from Elasticsearch. Please check the logs for further details.',
           statusCode: 503,
           headers: { 'Retry-After': '30' },
         });
@@ -161,7 +165,7 @@ export class AuthenticationService {
 
       if (authenticationResult.failed()) {
         const error = authenticationResult.error!;
-        this.logger.info(`Authentication attempt failed: ${getDetailedErrorMessage(error)}`);
+        this.logger.error(`Authentication attempt failed: ${getDetailedErrorMessage(error)}`);
 
         // proxy Elasticsearch "native" errors
         const statusCode = getErrorStatusCode(error);
@@ -242,11 +246,12 @@ export class AuthenticationService {
 
       if (!license.isLicenseAvailable() || !license.isEnabled()) {
         this.logger.error(
-          `License is not available or does not support security features, re-authentication is not possible (available: ${license.isLicenseAvailable()}, enabled: ${license.isEnabled()}).`
+          `License is not available or does not support security features, re-authentication is not possible (available: ${license.isLicenseAvailable()}, enabled: ${license.isEnabled()}, unavailable reason: ${license.getUnavailableReason()}).`
         );
         return toolkit.notHandled();
       }
 
+      // In theory, this should never happen since Core calls this handler only for `401` ("unauthorized") errors.
       if (getErrorStatusCode(error) !== 401) {
         this.logger.error(
           `Re-authentication is not possible for the following error: ${getDetailedErrorMessage(
@@ -297,7 +302,7 @@ export class AuthenticationService {
       } else if (authenticationResult.redirected()) {
         this.logger.error('Re-authentication failed since redirect is required.');
       } else {
-        this.logger.error('Re-authentication cannot be handled.');
+        this.logger.debug('Re-authentication cannot be handled.');
       }
 
       return toolkit.notHandled();
@@ -341,7 +346,7 @@ export class AuthenticationService {
       http.auth.get<AuthenticatedUser>(request).state ?? null;
 
     this.session = session;
-    this.authenticator = new Authenticator({
+    const authenticator = (this.authenticator = new Authenticator({
       audit,
       loggers,
       clusterClient,
@@ -358,7 +363,7 @@ export class AuthenticationService {
       session,
       isElasticCloudDeployment,
       customLogoutURL,
-    });
+    }));
 
     return {
       apiKeys: {
@@ -372,7 +377,41 @@ export class AuthenticationService {
         invalidateAsInternalUser: apiKeys.invalidateAsInternalUser.bind(apiKeys),
       },
 
-      login: this.authenticator.login.bind(this.authenticator),
+      login: async (request: KibanaRequest, attempt: ProviderLoginAttempt) => {
+        const providerIdentifier =
+          'name' in attempt.provider ? attempt.provider.name : attempt.provider.type;
+        this.logger.info(`Performing login attempt with "${providerIdentifier}" provider.`);
+
+        let loginResult: AuthenticationResult;
+        try {
+          loginResult = await authenticator.login(request, attempt);
+        } catch (err) {
+          this.logger.error(
+            `Login attempt with "${providerIdentifier}" provider failed due to unexpected error: ${getDetailedErrorMessage(
+              err
+            )}`
+          );
+          throw err;
+        }
+
+        if (loginResult.succeeded() || loginResult.redirected()) {
+          this.logger.info(
+            `Login attempt with "${providerIdentifier}" provider succeeded (requires redirect: ${loginResult.redirected()}).`
+          );
+        } else if (loginResult.failed()) {
+          this.logger.error(
+            `Login attempt with "${providerIdentifier}" provider failed: ${
+              loginResult.error ? getDetailedErrorMessage(loginResult.error) : 'unknown error'
+            }`
+          );
+        } else if (loginResult.notHandled()) {
+          this.logger.error(
+            `Login attempt with "${providerIdentifier}" provider cannot be handled.`
+          );
+        }
+
+        return loginResult;
+      },
       logout: this.authenticator.logout.bind(this.authenticator),
       acknowledgeAccessAgreement: this.authenticator.acknowledgeAccessAgreement.bind(
         this.authenticator

x-pack/plugins/security/server/authentication/authenticator.test.ts

@@ -378,13 +378,6 @@ describe('Authenticator', () => {
       authenticator = new Authenticator(mockOptions);
     });
 
-    it('fails if request is not provided.', async () => {
-      await expect(authenticator.login(undefined as any, undefined as any)).rejects.toThrowError(
-        'Request should be a valid "KibanaRequest" instance, was [undefined].'
-      );
-      expect(auditLogger.log).not.toHaveBeenCalled();
-    });
-
     it('fails if login attempt is not provided or invalid.', async () => {
       await expect(
         authenticator.login(httpServerMock.createKibanaRequest(), undefined as any)
@@ -1385,13 +1378,6 @@ describe('Authenticator', () => {
       authenticator = new Authenticator(mockOptions);
     });
 
-    it('fails if request is not provided.', async () => {
-      await expect(authenticator.authenticate(undefined as any)).rejects.toThrowError(
-        'Request should be a valid "KibanaRequest" instance, was [undefined].'
-      );
-      expect(auditLogger.log).not.toHaveBeenCalled();
-    });
-
     it('fails if an authentication provider fails.', async () => {
       const request = httpServerMock.createKibanaRequest();
       const failureReason = new Error('Not Authorized');
@@ -2418,12 +2404,6 @@ describe('Authenticator', () => {
       authenticator = new Authenticator(mockOptions);
     });
 
-    it('fails if request is not provided.', async () => {
-      await expect(authenticator.reauthenticate(undefined as any)).rejects.toThrowError(
-        'Request should be a valid "KibanaRequest" instance, was [undefined].'
-      );
-    });
-
     it('does not try to reauthenticate request if session is not available.', async () => {
       const request = httpServerMock.createKibanaRequest();
 
@@ -2463,6 +2443,7 @@ describe('Authenticator', () => {
 
     it('does not clear session if provider cannot handle authentication', async () => {
       const request = httpServerMock.createKibanaRequest();
+      mockOptions.session.getSID.mockResolvedValue(mockSessVal.sid);
       mockOptions.session.get.mockResolvedValue({ error: null, value: mockSessVal });
 
       mockBasicAuthenticationProvider.authenticate.mockResolvedValue(
@@ -2492,6 +2473,7 @@ describe('Authenticator', () => {
       mockBasicAuthenticationProvider.authenticate.mockResolvedValue(
         AuthenticationResult.failed(failureReason)
       );
+      mockOptions.session.getSID.mockResolvedValue(mockSessVal.sid);
       mockOptions.session.get.mockResolvedValue({ error: null, value: mockSessVal });
 
       await expect(authenticator.reauthenticate(request)).resolves.toEqual(
@@ -2512,6 +2494,7 @@ describe('Authenticator', () => {
       mockBasicAuthenticationProvider.authenticate.mockResolvedValue(
         AuthenticationResult.succeeded(user)
       );
+      mockOptions.session.getSID.mockResolvedValue(mockSessVal.sid);
       mockOptions.session.get.mockResolvedValue({ error: null, value: mockSessVal });
 
       await expect(authenticator.reauthenticate(request)).resolves.toEqual(
@@ -2534,6 +2517,7 @@ describe('Authenticator', () => {
       mockBasicAuthenticationProvider.authenticate.mockResolvedValue(
         AuthenticationResult.succeeded(user, { state: newState })
       );
+      mockOptions.session.getSID.mockResolvedValue(mockSessVal.sid);
       mockOptions.session.get.mockResolvedValue({ error: null, value: mockSessVal });
 
       await expect(authenticator.reauthenticate(request)).resolves.toEqual(
@@ -2560,6 +2544,7 @@ describe('Authenticator', () => {
       mockBasicAuthenticationProvider.authenticate.mockResolvedValue(
         AuthenticationResult.failed(failureReason)
       );
+      mockOptions.session.getSID.mockResolvedValue(mockSessVal.sid);
       mockOptions.session.get.mockResolvedValue({ error: null, value: mockSessVal });
 
       await expect(authenticator.reauthenticate(request)).resolves.toEqual(
@@ -2587,13 +2572,6 @@ describe('Authenticator', () => {
       authenticator = new Authenticator(mockOptions);
     });
 
-    it('fails if request is not provided.', async () => {
-      await expect(authenticator.logout(undefined as any)).rejects.toThrowError(
-        'Request should be a valid "KibanaRequest" instance, was [undefined].'
-      );
-      expect(auditLogger.log).not.toHaveBeenCalled();
-    });
-
     it('redirects to login form if session does not exist.', async () => {
       const request = httpServerMock.createKibanaRequest();
       mockBasicAuthenticationProvider.logout.mockResolvedValue(DeauthenticationResult.notHandled());

x-pack/plugins/security/server/authentication/authenticator.ts

@@ -6,7 +6,6 @@
  */
 
 import type { IBasePath, IClusterClient, KibanaRequest, LoggerFactory } from '@kbn/core/server';
-import { CoreKibanaRequest } from '@kbn/core/server';
 import type { Logger } from '@kbn/logging';
 import type { AuditServiceSetup } from '@kbn/security-plugin-types-server';
 import type { PublicMethodsOf } from '@kbn/utility-types';
@@ -46,6 +45,7 @@ import type { ConfigType } from '../config';
 import { getErrorStatusCode } from '../errors';
 import type { SecurityFeatureUsageServiceStart } from '../feature_usage';
 import {
+  getPrintableSessionId,
   type Session,
   SessionConcurrencyLimitError,
   SessionExpiredError,
@@ -137,13 +137,6 @@ const ACCESS_AGREEMENT_ROUTE = '/security/access_agreement';
  * The route to the overwritten session UI.
  */
 const OVERWRITTEN_SESSION_ROUTE = '/security/overwritten_session';
-
-function assertRequest(request: KibanaRequest) {
-  if (!(request instanceof CoreKibanaRequest)) {
-    throw new Error(`Request should be a valid "KibanaRequest" instance, was [${typeof request}].`);
-  }
-}
-
 function assertLoginAttempt(attempt: ProviderLoginAttempt) {
   if (!isLoginAttemptWithProviderType(attempt) && !isLoginAttemptWithProviderName(attempt)) {
     throw new Error(
@@ -296,7 +289,6 @@ export class Authenticator {
    * @param attempt Login attempt description.
    */
   async login(request: KibanaRequest, attempt: ProviderLoginAttempt) {
-    assertRequest(request);
     assertLoginAttempt(attempt);
 
     const { value: existingSessionValue } = await this.getSessionValue(request);
@@ -315,7 +307,7 @@ export class Authenticator {
         : [];
 
     if (providers.length === 0) {
-      this.logger.debug(
+      this.logger.warn(
         `Login attempt for provider with ${
           isLoginAttemptWithProviderName(attempt)
             ? `name ${attempt.provider.name}`
@@ -364,8 +356,6 @@ export class Authenticator {
    * @param request Request instance.
    */
   async authenticate(request: KibanaRequest): Promise<AuthenticationResult> {
-    assertRequest(request);
-
     const existingSession = await this.getSessionValue(request);
 
     if (this.shouldRedirectToLoginSelector(request, existingSession.value)) {
@@ -505,11 +495,21 @@ export class Authenticator {
    * @param request Request instance.
    */
   async reauthenticate(request: KibanaRequest) {
-    assertRequest(request);
+    // Return early if request doesn't have any associated session. We retrieve session ID separately from the session
+    // content because it doesn't trigger session invalidation for expired sessions.
+    const sid = await this.session.getSID(request);
+    if (!sid) {
+      this.logger.debug(
+        'Re-authentication is only supported for requests with associated sessions.'
+      );
+      return AuthenticationResult.notHandled();
+    }
 
     const { value: existingSessionValue } = await this.getSessionValue(request);
     if (!existingSessionValue) {
-      this.logger.warn('Session is no longer available and cannot be re-authenticated.');
+      this.logger
+        .get(getPrintableSessionId(sid))
+        .warn('Session is no longer available and cannot be re-authenticated.');
       return AuthenticationResult.notHandled();
     }
 
@@ -537,8 +537,6 @@ export class Authenticator {
    * @param request Request instance.
    */
   async logout(request: KibanaRequest) {
-    assertRequest(request);
-
     const { value: sessionValue } = await this.getSessionValue(request);
     const suggestedProviderName =
       sessionValue?.provider.name ??
@@ -577,8 +575,6 @@ export class Authenticator {
    * @param request Request instance.
    */
   async acknowledgeAccessAgreement(request: KibanaRequest) {
-    assertRequest(request);
-
     const { value: existingSessionValue } = await this.getSessionValue(request);
     const currentUser = this.options.getCurrentUser(request);
 
@@ -763,7 +759,7 @@ export class Authenticator {
     // invalidation (e.g. when Elasticsearch is temporarily unavailable).
     if (authenticationResult.failed()) {
       if (ownsSession && getErrorStatusCode(authenticationResult.error) === 401) {
-        this.logger.debug('Authentication attempt failed, existing session will be invalidated.');
+        this.logger.warn('Authentication attempt failed, existing session will be invalidated.');
         await this.invalidateSessionValue({ request, sessionValue: existingSessionValue });
       }
       return null;
@@ -799,7 +795,7 @@ export class Authenticator {
     // 3. If we re-authenticated user with another username (e.g. during IdP initiated SSO login or
     // when client certificate changes and PKI provider needs to re-authenticate user).
     if (providerHasChanged) {
-      this.logger.debug(
+      this.logger.warn(
         'Authentication provider has changed, existing session will be invalidated.'
       );
       await this.invalidateSessionValue({ request, sessionValue: existingSessionValue });
@@ -815,7 +811,7 @@ export class Authenticator {
       });
       existingSessionValue = null;
     } else if (usernameHasChanged) {
-      this.logger.debug('Username has changed, existing session will be invalidated.');
+      this.logger.warn('Username has changed, existing session will be invalidated.');
       await this.invalidateSessionValue({ request, sessionValue: existingSessionValue });
       existingSessionValue = null;
     }