backstage / backstage

Backstage is an open framework for building developer portals
https://backstage.io/
Apache License 2.0
26.61k stars 5.46k forks source link

🐛 Bug Report: Backstage express/morgan request logs do not identify the security principal making the request. #24620

Open vonjones opened 2 weeks ago

vonjones commented 2 weeks ago

📜 Description

Backstage does not populate the remote-user token within the morgan / express logger formats. When viewing the logs, one does not know which user or service is making the request and performing the action. This makes security forensics impossible.

I see two possible outcomes for this concern:

  1. make the core backstage correctly populate the remote_user within express / morgan logs.
  2. provide documentation on how users can perform this action. For example, if you feel that logging the name of the user is a PII concern, then at least tell others how to do it.

I'm able to work around this, and will post code in the ticket on how I'm doing so. I just feel like others in the community shouldn't have to figure this out, and it should work correctly out of the gate.

👍 Expected behavior

Log the security principal associated with the express request in the remote_user field. Like this:

[0] [1] 2024-05-03T14:05:13.992Z rootHttpRouter info ::1 - service:legacy-backend-to-backend [03/May/2024:14:05:13 +0000] "GET /api/catalog/entities?limit=500&offset=0 HTTP/1.1" 200 - "-" "node-fetch/1.0 (+https://github.com/bitinn/node-fetch)" type=incomingRequest
[0] [1] 2024-05-03T14:12:43.276Z rootHttpRouter info ::1 - user:default/von.jones [03/May/2024:14:12:43 +0000] "POST /api/catalog/entities/by-refs/ HTTP/1.1" 200 - "http://localhost:3000/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36" type=incomingRequest
[0] [1] 2024-05-03T14:21:52.282Z rootHttpRouter info ::1 - service:backstage-smoke-tests [03/May/2024:14:21:52 +0000] "GET /api/status/readiness HTTP/1.1" 200 15 "-" "curl/8.4.0" type=incomingRequest

👎 Actual Behavior with Screenshots

The remote_user field is not present in the logs. It shows as a dash, like this:

[0] [1] 2024-05-03T14:05:13.992Z rootHttpRouter info ::1 - - [03/May/2024:14:05:13 +0000] "GET /api/catalog/entities?limit=500&offset=0 HTTP/1.1" 200 - "-" "node-fetch/1.0 (+https://github.com/bitinn/node-fetch)" type=incomingRequest
[0] [1] 2024-05-03T14:12:43.276Z rootHttpRouter info ::1 - - [03/May/2024:14:12:43 +0000] "POST /api/catalog/entities/by-refs/ HTTP/1.1" 200 - "http://localhost:3000/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/124.0.0.0 Safari/537.36" type=incomingRequest
[0] [1] 2024-05-03T14:21:52.282Z rootHttpRouter info ::1 - - [03/May/2024:14:21:52 +0000] "GET /api/status/readiness HTTP/1.1" 200 15 "-" "curl/8.4.0" type=incomingRequest

👟 Reproduction steps

View the logs, filtered to requests.

📃 Provide the context for the Bug.

I am unable to track which actions are performed by which users on which teams. If a user reports a bug, I cannot view the logs associated with their requests. I am unable to discern which actions are user actions, which are backend service-to-service actions, and which are external API callers we created tokens for.

🖥️ Your Environment

OS: Darwin 23.4.0 - darwin/x64 node: v20.10.0 yarn: 1.22.19 cli: 0.26.2 (installed) backstage: 1.25.2

Dependencies: @backstage/app-defaults 1.5.3 @backstage/backend-app-api 0.6.2, 0.7.1 @backstage/backend-common 0.21.6, 0.21.7 @backstage/backend-defaults 0.2.17 @backstage/backend-dev-utils 0.1.4 @backstage/backend-openapi-utils 0.1.10, 0.1.9 @backstage/backend-plugin-api 0.6.16, 0.6.17 @backstage/backend-tasks 0.5.21, 0.5.22 @backstage/catalog-client 1.6.3, 1.6.4 @backstage/catalog-model 1.4.5 @backstage/cli-common 0.1.13 @backstage/cli-node 0.2.4, 0.2.5 @backstage/cli 0.26.2 @backstage/config-loader 1.7.0, 1.8.0 @backstage/config 1.2.0 @backstage/core-app-api 1.12.3 @backstage/core-compat-api 0.2.3, 0.2.4 @backstage/core-components 0.14.5 @backstage/core-plugin-api 1.9.1, 1.9.2 @backstage/dev-utils 1.0.30 @backstage/errors 1.2.4 @backstage/eslint-plugin 0.1.6 @backstage/frontend-plugin-api 0.6.3, 0.6.4 @backstage/integration-aws-node 0.1.12 @backstage/integration-react 1.1.25, 1.1.26 @backstage/integration 1.10.0, 1.9.1 @backstage/plugin-api-docs-module-protoc-gen-doc 0.1.6 @backstage/plugin-api-docs 0.11.3 @backstage/plugin-app-backend 0.3.64 @backstage/plugin-app-node 0.1.16 @backstage/plugin-auth-backend-module-atlassian-provider 0.1.8 @backstage/plugin-auth-backend-module-aws-alb-provider 0.1.8 @backstage/plugin-auth-backend-module-gcp-iap-provider 0.2.11 @backstage/plugin-auth-backend-module-github-provider 0.1.13 @backstage/plugin-auth-backend-module-gitlab-provider 0.1.13 @backstage/plugin-auth-backend-module-google-provider 0.1.13 @backstage/plugin-auth-backend-module-microsoft-provider 0.1.11 @backstage/plugin-auth-backend-module-oauth2-provider 0.1.13 @backstage/plugin-auth-backend-module-oauth2-proxy-provider 0.1.9 @backstage/plugin-auth-backend-module-oidc-provider 0.1.7 @backstage/plugin-auth-backend-module-okta-provider 0.0.9 @backstage/plugin-auth-backend 0.22.3 @backstage/plugin-auth-node 0.4.11, 0.4.12 @backstage/plugin-auth-react 0.0.3 @backstage/plugin-catalog-backend-module-github 0.5.7 @backstage/plugin-catalog-backend-module-scaffolder-entity-model 0.1.14 @backstage/plugin-catalog-backend 1.21.0 @backstage/plugin-catalog-common 1.0.22 @backstage/plugin-catalog-graph 0.4.3 @backstage/plugin-catalog-import 0.10.9 @backstage/plugin-catalog-node 1.11.0, 1.11.1 @backstage/plugin-catalog-react 1.11.2, 1.11.3 @backstage/plugin-catalog 1.18.2 @backstage/plugin-events-backend-module-github 0.2.3 @backstage/plugin-events-backend 0.3.4 @backstage/plugin-events-node 0.3.3, 0.3.2 @backstage/plugin-home-react 0.1.11 @backstage/plugin-home 0.7.2 @backstage/plugin-org 0.6.23 @backstage/plugin-permission-common 0.7.13 @backstage/plugin-permission-node 0.7.27, 0.7.28 @backstage/plugin-permission-react 0.4.21, 0.4.22 @backstage/plugin-proxy-backend 0.4.14 @backstage/plugin-scaffolder-backend-module-azure 0.1.8 @backstage/plugin-scaffolder-backend-module-bitbucket-cloud 0.1.6 @backstage/plugin-scaffolder-backend-module-bitbucket-server 0.1.6 @backstage/plugin-scaffolder-backend-module-bitbucket 0.2.6 @backstage/plugin-scaffolder-backend-module-gerrit 0.1.8 @backstage/plugin-scaffolder-backend-module-gitea 0.1.6 @backstage/plugin-scaffolder-backend-module-github 0.2.6, 0.2.7 @backstage/plugin-scaffolder-backend-module-gitlab 0.3.2 @backstage/plugin-scaffolder-backend 1.22.3 @backstage/plugin-scaffolder-common 1.5.1 @backstage/plugin-scaffolder-node 0.4.2, 0.4.3 @backstage/plugin-scaffolder-react 1.8.3 @backstage/plugin-scaffolder 1.19.2 @backstage/plugin-search-backend-module-catalog 0.1.21 @backstage/plugin-search-backend-module-pg 0.5.25 @backstage/plugin-search-backend-module-techdocs 0.1.21 @backstage/plugin-search-backend-node 1.2.20 @backstage/plugin-search-backend 1.5.6 @backstage/plugin-search-common 1.2.11 @backstage/plugin-search-react 1.7.10, 1.7.9 @backstage/plugin-search 1.4.9 @backstage/plugin-techdocs-backend 1.10.3 @backstage/plugin-techdocs-module-addons-contrib 1.1.8 @backstage/plugin-techdocs-node 1.12.2 @backstage/plugin-techdocs-react 1.2.2 @backstage/plugin-techdocs 1.10.3 @backstage/plugin-user-settings 0.8.4 @backstage/release-manifests 0.0.11 @backstage/test-utils 1.5.3 @backstage/theme 0.5.2, 0.5.3 @backstage/types 1.1.1 @backstage/version-bridge 1.0.7, 1.0.8 ✨ Done in 1.27s.

👀 Have you spent some time to check if this bug has been raised before?

🏢 Have you read the Code of Conduct?

Are you willing to submit PR?

No, but I'm happy to collaborate on a PR with someone else

vonjones commented 2 weeks ago

Here's how I'm solving this in the new backend systems. Note that the code could be much simpler if the core service set the req.credential somewhere, as the prior backend system set req.user in packages/backend/src/authMiddleware.ts:

// src/packages/backend/src/services/LoggingAugmenterService.ts
import {
  coreServices,
  createServiceFactory,
} from '@backstage/backend-plugin-api';
import { Request, RequestHandler } from 'express';
import morgan from 'morgan';
import { getRootLogger } from '@backstage/backend-common';
import { createServiceRef } from '@backstage/backend-plugin-api';
import { ServerResponse } from 'http';

interface LoggingAugmenterService {}

const loggingAugmenterServiceRef = createServiceRef<LoggingAugmenterService>({
  id: 'wpe-loging-augmenter',
});

// Test this using source .env && curl -H "Authorization: Bearer $<ENVVAR like GROUP_GENERATION_SECRET>" -H  -X GET  http://localhost:7007/api/status/readiness

// Ref: https://backstage.io/docs/backend-system/architecture/services/
// Ref: https://github.com/backstage/backstage/blob/master/docs/plugins/backend-plugin.md#making-use-of-the-users-identity
// Ref: https://github.com/backstage/backstage/blob/9910c6babc104d8b765c9646ee89604b09dc15de/packages/backend-app-api/src/services/implementations/httpAuth/httpAuthServiceFactory.ts#L126
// Ref: https://github.com/backstage/backstage/blob/9910c6babc104d8b765c9646ee89604b09dc15de/packages/backend-app-api/src/services/implementations/httpRouter/httpRouterServiceFactory.ts#L79
// Ref: https://github.com/backstage/backstage/blob/9910c6babc104d8b765c9646ee89604b09dc15de/packages/backend-app-api/src/services/implementations/httpRouter/createCredentialsBarrier.ts#L62
export const loggingAugmenterService = createServiceFactory(() => ({
  service: loggingAugmenterServiceRef,
  initialization: 'always',
  deps: {
    httpRouter: coreServices.httpRouter,
    httpAuth: coreServices.httpAuth,
  },
  factory({ httpRouter, httpAuth }) {
    const credentialAugmenterMiddleware: RequestHandler = async (
      req: Request,
      _,
      next,
    ) => {
      const credentials = await httpAuth.credentials(req);
      // we are adding the credentials to the request object for logging purposes, Used by the morgan.token code below.
      // @ts-ignore we are adding a field not in the original interface
      req.credentials = credentials;
      next();
      return;
    };
    httpRouter.use(credentialAugmenterMiddleware);
    return {};
  },
}));

// log the remote-user field in common logging formats of express request logs
// Ref: https://expressjs.com/en/resources/middleware/morgan.html
morgan.token('remote-user', function getRemoteUserToken(req: Request, res: ServerResponse) {
  try {
    const credentials: any =
      // since morgan.token does now allow us to make the async call, we added this to the request object above in the service
      // @ts-ignore we are adding a field not in the original interface
      req?.credentials;

    if (credentials && credentials?.principal?.type !== 'none') {
      if (credentials.principal?.type === 'user') {
        return credentials.principal.userEntityRef;
      }
      if (credentials.principal?.type === 'service') {
        return `${credentials.principal.type}:${credentials.principal.subject}`;
      }
    }

    if (
      (req.baseUrl === '/api/cookie' && req.path === '/') ||
      req.path?.startsWith('/api/auth/okta/') ||
      req.baseUrl === '/api/auth/okta' ||
      req.path?.startsWith('/api/auth/google/') ||
      req.baseUrl === '/api/auth/google' ||
      req.path?.startsWith('/api/auth/github/') ||
      req.baseUrl === '/api/auth/github'
    ) {
      // calls to the identity system in the process of authenticating the user
      return 'anonymous-authenticating';
    }
    if ([200, 304].includes(res.statusCode)) {
      return 'unauthenticated:public-content';
    }

    // this should be an error case
    return 'unauthenticated:error';
  } catch (error) {
    getRootLogger().error(
      `Error identifying the remote-user for logging: ${error}`,
    );
  }
  return 'remote-user-error';
});
// src/packages/backend/src/index.ts
...
import { loggingAugmenterService } from './services/LoggingAugmenterService';

...
const backend = createBackend();
...
/*
 * Backstage extension services, from the src/packages/backend/src/services directory
 */
backend.add(loggingAugmenterService);

backend.start();
vonjones commented 2 weeks ago

Here's how I was doing it with the old backend system, extending the prior service-to-service auth pattern:

// packages/backend/src/authMiddleware.ts
...
export const createAuthMiddleware = async (
  config: Config,
  appEnv: PluginEnvironment,
) => {
...
      try {
        req.user = await appEnv.identity.getIdentity({ request: req });
      } catch {
...
}

// log the remote-user field in common logging formats of express request logs
morgan.token('remote-user', function getRemoteUserToken(req: Request) {
  try {
    const identity: BackstageIdentityResponse | undefined =
      req?.user as BackstageIdentityResponse;

    if (identity?.identity?.type === 'user') {
      // an authenticated user
      return identity?.identity?.userEntityRef;
    }
    if (identity?.identity?.type === SERVER_TOKEN_SUB) {
      // an authenticated server-to-server request, Ref:
      // https://github.com/backstage/backstage/blob/master/contrib/docs/tutorials/authenticate-api-requests.md
      // It could also be an external API caller that is authorized via
      // https://backstage.io/docs/auth/service-to-service-auth/#usage-in-external-callers . Ideally,
      // the user agent identifies the caller, which is logged separately.
      return 'backstage-or-external-api-caller';
    }
    if (
      (req.baseUrl === '/api/cookie' && req.path === '/') ||
      req.path?.startsWith('/api/auth/okta/') ||
      req.baseUrl === '/api/auth/okta' ||
      req.path?.startsWith('/api/auth/google/') ||
      req.baseUrl === '/api/auth/google' ||
      req.path?.startsWith('/api/auth/github/') ||
      req.baseUrl === '/api/auth/github'
    ) {
      // calls to the identity system in the process of authenticating the user
      return 'anonymous-authenticating';
    }
    // Ref: https://github.com/backstage/backstage/blob/master/packages/app/public/
    const publicDirectoryContents = [
      "/android-chrome-192x192.png",
      "/android-chrome-512x512.png",
      "/apple-touch-icon.png",
      "/favicon-16x16.png",
      "/favicon-32x32.png",
      "/favicon.ico",
      "/favicon.svg",
      "/index.html",
      "/manifest.json",
      "/robots.txt",
      "/safari-pinned-tab.svg"
    ];
    if (
      (req.baseUrl === '/api/auth' && req.path === '/.well-known/jwks.json') ||
      req.baseUrl.startsWith('/static') || req.path.startsWith('/static') || 
      (req.baseUrl === '' && publicDirectoryContents.includes(req.path)) ||
      (req.path.includes('/assets/stylesheets/'))
    ) {
      // public APIs which are intentionally unauthenticated
      return 'anonymous-public-content';
    }

    // this should be an error case
    return 'anonymous-other';
  } catch (error) {
    getRootLogger().error(`Error identifying the remote-user for logging: ${error}`);
  }
  return 'remote-user-error'
});
Rugvip commented 2 weeks ago

Love the idea! 👍

I think we may need to explore other options to using morgan, the lack of async isn't a non-starter but it's certainly not great. Bigger issue is that it's a singleton and we're mutating that state within our service implementation, making it hard to customize cleanly

aramissennyeydd commented 1 week ago

This might also be possibly related to #21605, and a larger conversation about audit trails where logging may be one of a few venues where this information is tracked.