[CORL-281] Metrics (#2298)

* feat: iunitial metrics implementation

* fix: graphql endpoint was throwing errors.

* feat: add metrics env variables to readme

src/core/index.ts

@@ -5,9 +5,7 @@ import Server, { ServerOptions } from "./server";
  *
  * @param options ServerOptions that will be used to configure Talk.
  */
-export default async function createTalk(
-  options: ServerOptions = {}
-): Promise<Server> {
+export default function createTalk(options: ServerOptions = {}): Server {
   // Create the server with the provided options.
   return new Server(options);
 }

src/core/server/app/helpers/entrypoints.ts

@@ -104,7 +104,10 @@ export default class Entrypoints {
       // Create and return the entrypoints.
       return new Entrypoints(manifest);
     } catch (err) {
-      logger.error({ err }, "could not load the manifest");
+      logger.error(
+        { err },
+        "could not load the manifest, maybe you need to run `npm run build`"
+      );
       return null;
     }
   }

src/core/server/app/index.ts

@@ -20,6 +20,7 @@ import { AugmentedRedis } from "talk-server/services/redis";
 import TenantCache from "talk-server/services/tenant/cache";
 
 import { accessLogger, errorLogger } from "./middleware/logging";
+import { metricsRecorder } from "./middleware/metrics";
 import serveStatic from "./middleware/serveStatic";
 import { createRouter } from "./router";
 
@@ -34,6 +35,7 @@ export interface AppOptions {
   schema: GraphQLSchema;
   signingConfig: JWTSigningConfig;
   tenantCache: TenantCache;
+  metrics: boolean;
 }
 
 /**
@@ -49,6 +51,9 @@ export async function createApp(options: AppOptions): Promise<Express> {
   // Logging
   parent.use(accessLogger);
 
+  // Capturing metrics.
+  parent.use(metricsRecorder());
+
   // Create some services for the router.
   const passport = createPassport(options);
 

src/core/server/app/middleware/basicAuth.ts

@@ -0,0 +1,32 @@
+import auth from "basic-auth";
+import compare from "tsscmp";
+
+import { RequestHandler } from "talk-server/types/express";
+
+export const basicAuth = (
+  username: string,
+  password: string
+): RequestHandler => {
+  function check(name: string, pass: string) {
+    let valid = true;
+
+    // Simple method to prevent short-circuit and use timing-safe compare.
+    valid = compare(name, username) && valid;
+    valid = compare(pass, password) && valid;
+
+    return valid;
+  }
+
+  return (req, res, next) => {
+    // Pull the credentials out of the request.
+    const credentials = auth(req);
+
+    // Check credentials
+    if (credentials && check(credentials.name, credentials.pass)) {
+      return next();
+    }
+
+    res.setHeader("WWW-Authenticate", `Basic realm="${req.originalUrl}"`);
+    res.status(401).send("Access denied");
+  };
+};

src/core/server/app/middleware/error.ts

@@ -1,5 +1,6 @@
 import { ErrorRequestHandler } from "express";
 
+import { FluentBundle } from "fluent/compat";
 import { InternalError, TalkError } from "talk-server/errors";
 import { I18n } from "talk-server/services/i18n";
 import { Request } from "talk-server/types/express";
@@ -22,11 +23,14 @@ const wrapError = (err: Error) =>
  * @param bundles the translation bundles
  * @param tenant the optional tenant to use when selecting the language
  */
-const serializeError = (err: TalkError, req: Request, bundles: I18n) => {
+const serializeError = (err: TalkError, req: Request, bundles?: I18n) => {
   // Get the translation bundle.
-  let bundle = bundles.getDefaultBundle();
-  if (req.talk && req.talk.tenant) {
-    bundle = bundles.getBundle(req.talk.tenant.locale);
+  let bundle: FluentBundle | null = null;
+  if (bundles) {
+    bundle = bundles.getDefaultBundle();
+    if (req.talk && req.talk.tenant) {
+      bundle = bundles.getBundle(req.talk.tenant.locale);
+    }
   }
 
   return {
@@ -34,7 +38,7 @@ const serializeError = (err: TalkError, req: Request, bundles: I18n) => {
   };
 };
 
-export const JSONErrorHandler = (bundles: I18n): ErrorRequestHandler => (
+export const JSONErrorHandler = (bundles?: I18n): ErrorRequestHandler => (
   err,
   req,
   res,
@@ -47,7 +51,7 @@ export const JSONErrorHandler = (bundles: I18n): ErrorRequestHandler => (
   res.status(err.status).json(serializeError(err, req, bundles));
 };
 
-export const HTMLErrorHandler = (bundles: I18n): ErrorRequestHandler => (
+export const HTMLErrorHandler = (bundles?: I18n): ErrorRequestHandler => (
   err,
   req,
   res,

src/core/server/app/middleware/graphql/index.ts

@@ -1,6 +1,7 @@
 import { GraphQLOptions } from "apollo-server-express";
 import { Handler } from "express";
 import { FieldDefinitionNode, GraphQLError, ValidationContext } from "graphql";
+import { Counter, Histogram } from "prom-client";
 
 // TODO: when https://github.com/apollographql/apollo-server/pull/1907 is merged, update this import path
 import {
@@ -13,6 +14,7 @@ import { Config } from "talk-server/config";
 import {
   ErrorWrappingExtension,
   LoggerExtension,
+  MetricsExtension,
 } from "talk-server/graph/common/extensions";
 
 export * from "./batch";
@@ -42,6 +44,20 @@ export const graphqlMiddleware = (
   config: Config,
   requestOptions: ExpressGraphQLOptionsFunction
 ): Handler => {
+  // Configure the metrics handlers.
+  const executedGraphQueriesTotalCounter = new Counter({
+    name: "talk_executed_graph_queries_total",
+    help: "number of GraphQL queries executed",
+    labelNames: ["operation_type", "operation_name"],
+  });
+
+  const graphQLExecutionTimingsHistogram = new Histogram({
+    name: "talk_executed_graph_queries_timings",
+    help: "timings for execution times of GraphQL operations",
+    buckets: [0.1, 5, 15, 50, 100, 500],
+    labelNames: ["operation_type", "operation_name"],
+  });
+
   // Create a new baseOptions that will be merged into the new options.
   const baseOptions: Omit<GraphQLOptions, "schema"> = {
     // Disable the debug mode, as we already add in our logging function.
@@ -50,6 +66,12 @@ export const graphqlMiddleware = (
     extensions: [
       () => new ErrorWrappingExtension(),
       () => new LoggerExtension(),
+      () =>
+        // Pass the metrics to the extension so it can increment.
+        new MetricsExtension({
+          executedGraphQueriesTotalCounter,
+          graphQLExecutionTimingsHistogram,
+        }),
     ],
   };
 

src/core/server/app/middleware/logging.ts

@@ -1,26 +1,19 @@
 import { ErrorRequestHandler, RequestHandler } from "express";
+import onFinished from "on-finished";
 import now from "performance-now";
 
 import logger from "talk-server/logger";
 
 export const accessLogger: RequestHandler = (req, res, next) => {
   const startTime = now();
-  const end = res.end;
-  res.end = (chunk: any, encodingOrCb?: any, cb?: any) => {
+
+  onFinished(res, () => {
     // Compute the end time.
     const responseTime = Math.round(now() - startTime);
 
     // Get some extra goodies from the request.
     const userAgent = req.get("User-Agent");
 
-    // Reattach the old end, and finish.
-    res.end = end;
-    if (typeof encodingOrCb === "function") {
-      res.end(chunk, encodingOrCb);
-    } else {
-      res.end(chunk, encodingOrCb, cb);
-    }
-
     // Log this out.
     logger.info(
       {
@@ -33,7 +26,7 @@ export const accessLogger: RequestHandler = (req, res, next) => {
       },
       "http request"
     );
-  };
+  });
 
   next();
 };

src/core/server/app/middleware/metrics.ts

@@ -0,0 +1,38 @@
+import { RequestHandler } from "express";
+import onFinished from "on-finished";
+import now from "performance-now";
+import { Counter, Histogram } from "prom-client";
+
+export const metricsRecorder = (): RequestHandler => {
+  const httpRequestsTotal = new Counter({
+    name: "http_requests_total",
+    help: "Total number of HTTP requests made.",
+    labelNames: ["code", "method"],
+  });
+
+  const httpRequestDurationMilliseconds = new Histogram({
+    name: "http_request_duration_milliseconds",
+    help: "Histogram of latencies for HTTP requests.",
+    buckets: [0.1, 5, 15, 50, 100, 500],
+    labelNames: ["method", "handler"],
+  });
+
+  return (req, res, next) => {
+    const startTime = now();
+
+    onFinished(res, () => {
+      // Compute the end time.
+      const responseTime = Math.round(now() - startTime);
+
+      // Increment the request counter.
+      httpRequestsTotal.labels(`${res.statusCode}`, req.method).inc();
+
+      // Add the request duration.
+      httpRequestDurationMilliseconds
+        .labels(req.method, req.baseUrl + req.path)
+        .observe(responseTime);
+    });
+
+    next();
+  };
+};

src/core/server/app/router/index.ts

@@ -1,5 +1,6 @@
 import express, { Router } from "express";
 import path from "path";
+import { register } from "prom-client";
 
 import { AppOptions } from "talk-server/app";
 import { noCacheMiddleware } from "talk-server/app/middleware/cacheHeaders";
@@ -11,6 +12,7 @@ import { RouterOptions } from "talk-server/app/router/types";
 import logger from "talk-server/logger";
 
 import Entrypoints from "../helpers/entrypoints";
+import { basicAuth } from "../middleware/basicAuth";
 import { createAPIRouter } from "./api";
 import { createClientTargetRouter } from "./client";
 
@@ -131,6 +133,26 @@ export function createRouter(app: AppOptions, options: RouterOptions) {
     );
   }
 
+  if (app.metrics) {
+    // Add basic auth if provided.
+    const username = app.config.get("metrics_username");
+    const password = app.config.get("metrics_password");
+    if (username && password) {
+      router.use("/metrics", basicAuth(username, password));
+      logger.info("adding authentication to metrics endpoint");
+    } else {
+      logger.info(
+        "not adding authentication to metrics endpoint, credentials not provided"
+      );
+    }
+
+    router.get("/metrics", noCacheMiddleware, (req, res) => {
+      res.set("Content-Type", register.contentType);
+      res.end(register.metrics());
+    });
+    logger.info({ path: "/metrics" }, "mounting metrics path on app");
+  }
+
   return router;
 }
 

src/core/server/config.ts

@@ -81,6 +81,28 @@ const config = convict({
     env: "PORT",
     arg: "port",
   },
+  cluster_metrics_port: {
+    doc: "The port to bind for cluster metrics.",
+    format: "port",
+    default: 3001,
+    env: "CLUSTER_METRICS_PORT",
+    arg: "clusterMetricsPort",
+  },
+  metrics_username: {
+    doc: "The username to use to authenticate to the metrics endpoint.",
+    format: "String",
+    default: "",
+    env: "METRICS_USERNAME",
+    arg: "metricsUsername",
+  },
+  metrics_password: {
+    doc: "The password to use to authenticate to the metrics endpoint.",
+    format: "String",
+    default: "",
+    env: "METRICS_PASSWORD",
+    arg: "metricsPassword",
+    sensitive: true,
+  },
   dev_port: {
     doc: "The port to bind for the Webpack Dev Server.",
     format: "port",

src/core/server/errors/index.ts

@@ -172,13 +172,18 @@ export class TalkError extends VError {
     this.param = param;
   }
 
-  public serializeExtensions(bundle: FluentBundle): TalkErrorExtensions {
-    const message = translate(
-      bundle,
-      this.code,
-      ERROR_TRANSLATIONS[this.code],
-      this.context.pub
-    );
+  public serializeExtensions(bundle: FluentBundle | null): TalkErrorExtensions {
+    let message: string;
+    if (bundle) {
+      message = translate(
+        bundle,
+        this.code,
+        ERROR_TRANSLATIONS[this.code],
+        this.context.pub
+      );
+    } else {
+      message = this.code;
+    }
 
     return {
       id: this.id,

src/core/server/graph/common/extensions/LoggerExtension.ts

@@ -1,9 +1,4 @@
-import {
-  DocumentNode,
-  ExecutionArgs,
-  GraphQLError,
-  OperationDefinitionNode,
-} from "graphql";
+import { ExecutionArgs, GraphQLError } from "graphql";
 import {
   EndHandler,
   GraphQLExtension,
@@ -12,33 +7,13 @@ import {
 import now from "performance-now";
 
 import CommonContext from "talk-server/graph/common/context";
+import { getOperationMetadata } from "./helpers";
 
 export function logError(ctx: CommonContext, err: GraphQLError) {
   ctx.logger.error({ err }, "graphql query error");
 }
 
 export class LoggerExtension implements GraphQLExtension<CommonContext> {
-  private getOperationMetadata(doc: DocumentNode) {
-    if (doc.kind === "Document") {
-      const operationDefinition = doc.definitions.find(
-        ({ kind }) => kind === "OperationDefinition"
-      ) as OperationDefinitionNode | undefined;
-      if (operationDefinition) {
-        let operationName: string | undefined;
-        if (operationDefinition.name) {
-          operationName = operationDefinition.name.value;
-        }
-
-        return {
-          operationName,
-          operation: operationDefinition.operation,
-        };
-      }
-    }
-
-    return {};
-  }
-
   public executionDidStart(o: {
     executionArgs: ExecutionArgs;
   }): EndHandler | void {
@@ -55,7 +30,7 @@ export class LoggerExtension implements GraphQLExtension<CommonContext> {
         o.executionArgs.contextValue.logger.debug(
           {
             responseTime,
-            ...this.getOperationMetadata(o.executionArgs.document),
+            ...getOperationMetadata(o.executionArgs.document),
           },
           "graphql query"
         );

src/core/server/graph/common/extensions/MetricsExtension.ts

@@ -0,0 +1,51 @@
+import { ExecutionArgs } from "graphql";
+import { EndHandler, GraphQLExtension } from "graphql-extensions";
+import now from "performance-now";
+import { Counter, Histogram } from "prom-client";
+
+import CommonContext from "talk-server/graph/common/context";
+import { getOperationMetadata } from "./helpers";
+
+export interface MetricsExtensionOptions {
+  executedGraphQueriesTotalCounter: Counter;
+  graphQLExecutionTimingsHistogram: Histogram;
+}
+
+export class MetricsExtension implements GraphQLExtension<CommonContext> {
+  private options: MetricsExtensionOptions;
+
+  constructor(options: MetricsExtensionOptions) {
+    this.options = options;
+  }
+
+  public executionDidStart(o: {
+    executionArgs: ExecutionArgs;
+  }): EndHandler | void {
+    // Only try to log things if the context is provided.
+    if (o.executionArgs.contextValue) {
+      // Grab the start time so we can calculate the time it takes to execute
+      // the graph query.
+      const startTime = now();
+      return () => {
+        // Compute the end time.
+        const responseTime = Math.round(now() - startTime);
+
+        // Get the request metadata.
+        const { operation, operationName } = getOperationMetadata(
+          o.executionArgs.document
+        );
+
+        if (operation && operationName) {
+          // Increment the graph query value, tagging with the name of the query.
+          this.options.executedGraphQueriesTotalCounter
+            .labels(operation, operationName)
+            .inc();
+
+          this.options.graphQLExecutionTimingsHistogram
+            .labels(operation, operationName)
+            .observe(responseTime);
+        }
+      };
+    }
+  }
+}

src/core/server/graph/common/extensions/helpers.ts

@@ -0,0 +1,22 @@
+import { DocumentNode, OperationDefinitionNode } from "graphql";
+
+export function getOperationMetadata(doc: DocumentNode) {
+  if (doc.kind === "Document") {
+    const operationDefinition = doc.definitions.find(
+      ({ kind }) => kind === "OperationDefinition"
+    ) as OperationDefinitionNode | undefined;
+    if (operationDefinition) {
+      let operationName: string | undefined;
+      if (operationDefinition.name) {
+        operationName = operationDefinition.name.value;
+      }
+
+      return {
+        operationName,
+        operation: operationDefinition.operation,
+      };
+    }
+  }
+
+  return {};
+}

src/core/server/graph/common/extensions/index.ts

@@ -1,2 +1,3 @@
 export * from "./ErrorWrappingExtension";
 export * from "./LoggerExtension";
+export * from "./MetricsExtension";

src/core/server/index.ts

@@ -1,7 +1,9 @@
+import cluster from "cluster";
 import express, { Express } from "express";
 import { GraphQLSchema } from "graphql";
 import http from "http";
 import { Db } from "mongodb";
+import { AggregatorRegistry, collectDefaultMetrics } from "prom-client";
 
 import { LanguageCode } from "talk-common/helpers/i18n/locales";
 import { createApp, listenAndServe } from "talk-server/app";
@@ -19,6 +21,11 @@ import {
   createRedisClient,
 } from "talk-server/services/redis";
 import TenantCache from "talk-server/services/tenant/cache";
+import { basicAuth } from "./app/middleware/basicAuth";
+import { noCacheMiddleware } from "./app/middleware/cacheHeaders";
+import { JSONErrorHandler } from "./app/middleware/error";
+import { accessLogger, errorLogger } from "./app/middleware/logging";
+import { notFoundMiddleware } from "./app/middleware/notFound";
 
 export interface ServerOptions {
   /**
@@ -27,6 +34,10 @@ export interface ServerOptions {
   config?: Config;
 }
 
+export interface ServerStartOptions {
+  parent?: Express;
+}
+
 /**
  * Server provides an interface to create, start, and manage a Talk Server.
  */
@@ -122,6 +133,9 @@ class Server {
       tenantCache: this.tenantCache,
       i18n: this.i18n,
     });
+
+    // Setup the metrics collectors.
+    collectDefaultMetrics({ timeout: 5000 });
   }
 
   /**
@@ -146,6 +160,62 @@ class Server {
     // Launch all of the job processors.
     this.tasks.mailer.process();
     this.tasks.scraper.process();
+
+    // If we are running in concurrency mode, and we are the master, we should
+    // setup the aggregator for the cluster metrics.
+    if (cluster.isMaster && this.config.get("concurrency") > 1) {
+      // Create the aggregator registry for metrics.
+      const aggregatorRegistry = new AggregatorRegistry();
+
+      // Setup the cluster metrics server.
+      const metricsServer = express();
+
+      // Setup access logger.
+      metricsServer.use(accessLogger);
+
+      // Add basic auth if provided.
+      const username = this.config.get("metrics_username");
+      const password = this.config.get("metrics_password");
+      if (username && password) {
+        metricsServer.use("/cluster_metrics", basicAuth(username, password));
+        logger.info("adding authentication to metrics endpoint");
+      } else {
+        logger.info(
+          "not adding authentication to metrics endpoint, credentials not provided"
+        );
+      }
+
+      // Cluster metrics will be served on /cluster_metrics.
+      metricsServer.get(
+        "/cluster_metrics",
+        noCacheMiddleware,
+        (req, res, next) => {
+          aggregatorRegistry.clusterMetrics((err, metrics) => {
+            if (err) {
+              return next(err);
+            }
+
+            res.set("Content-Type", aggregatorRegistry.contentType);
+            res.send(metrics);
+          });
+        }
+      );
+
+      // Error handling.
+      metricsServer.use(notFoundMiddleware);
+      metricsServer.use(errorLogger);
+      metricsServer.use(JSONErrorHandler());
+
+      const port = this.config.get("cluster_metrics_port");
+
+      // Star the server listening for cluster metrics.
+      await listenAndServe(metricsServer, port);
+
+      logger.info(
+        { port, path: "/cluster_metrics" },
+        "now listening for cluster metrics"
+      );
+    }
   }
 
   /**
@@ -154,7 +224,7 @@ class Server {
    *
    * @param parent the optional express application to bind the server to.
    */
-  public async start(parent?: Express) {
+  public async start({ parent }: ServerStartOptions) {
     // Guard against not being connected.
     if (!this.connected) {
       throw new Error("server has not connected yet");
@@ -168,6 +238,9 @@ class Server {
     // Create the signing config.
     const signingConfig = createJWTSigningConfig(this.config);
 
+    // Only enable the metrics server if concurrency is set to 1.
+    const metrics = this.config.get("concurrency") === 1;
+
     // Create the Talk App, branching off from the parent app.
     const app: Express = await createApp({
       parent,
@@ -180,6 +253,7 @@ class Server {
       i18n: this.i18n,
       mailerQueue: this.tasks.mailer,
       scraperQueue: this.tasks.scraper,
+      metrics,
     });
 
     // Start the application and store the resulting http.Server. The server

src/index.ts

@@ -36,15 +36,15 @@ import Server from "./core/server";
 import logger from "./core/server/logger";
 
 // Create the app that will serve as the mounting point for the Talk Server.
-const app = express();
+const parent = express();
 
 // worker will start the worker process.
 async function worker(server: Server) {
   try {
-    logger.debug("started server worker");
-
     // Start the server.
-    await server.start(app);
+    await server.start({ parent });
+
+    logger.debug("started server worker");
   } catch (err) {
     logger.error({ err }, "can not start server in worker mode");
     throw err;
@@ -57,10 +57,10 @@ async function master(server: Server) {
   logger.debug({ workerCount }, "spawning workers to handle traffic");
 
   try {
-    logger.debug("started server master");
-
     // Process jobs.
     await server.process();
+
+    logger.debug("started server master");
   } catch (err) {
     logger.error({ err }, "can not start server in master mode");
     throw err;
@@ -73,7 +73,7 @@ async function bootstrap() {
     logger.debug("starting bootstrap");
 
     // Create the server instance.
-    const server = await createTalk();
+    const server = createTalk();
 
     // Determine the number of workers.
     const workerCount = server.config.get("concurrency");
@@ -91,7 +91,7 @@ async function bootstrap() {
       await server.process();
 
       // Start the server.
-      await server.start(app);
+      await server.start({ parent });
     } else {
       // Launch the server start within throng.
       throng({

src/types/tsscmp.d.ts

@@ -0,0 +1,3 @@
+declare module "tsscmp" {
+  export default function tsscmp(expect: string, got: string): boolean;
+}