Add structured logging and Prometheus events

packages/attestation-service/README.md

@@ -19,6 +19,18 @@ You can use the following environment variables to configure the attestation ser
 - `NEXMO_SECRET` - The API secret to the Nexmo API
 - `NEXMO_BLACKLIST` - A comma-sperated list of country codes you do not want to serve
 
+`twilio`
+
+- `TWILIO_ACCOUNT_SID` - The SID of your Twilio account
+- `TWILIO_MESSAGE_SERVICE_SID` - The SID of the messaging service you want to use. The messaging service should have at least 1 phone number associated with it.
+- `TWILIO_AUTH_TOKEN` - The auth token for your Twilio account
+
+### Operations
+
+This service uses `bunyan` for structured logging with JSON lines. You can pipe STDOUT to `yarn run bunyan` for a more human friendly output. The `LOG_LEVEL` environment variable can specify desired log levels. With `LOG_FORMAT=stackdriver` you can get stackdriver specific format to recover information such as error traces etc.
+
+This service exposes prometheus metrics under `/metrics`.
+
 ### Running locally
 
 After checking out the source, you should create a local sqlite database by running:

packages/attestation-service/config/.env.development

@@ -11,3 +11,7 @@ TWILIO_ACCOUNT_SID=x
 TWILIO_MESSAGING_SERVICE_SID=x
 TWILIO_AUTH_TOKEN=x
 TWILIO_BLACKLIST=
+# Options: default, stackdriver
+LOG_FORMAT=
+# Options: fatal, error, warn, info, debug, trace
+LOG_LEVEL=

packages/attestation-service/index.d.ts

@@ -1 +1,2 @@
 declare module 'nexmo'
+declare module 'express-request-id'

packages/attestation-service/package.json

@@ -31,6 +31,8 @@
     "@celo/utils": "^0.1.0",
     "bignumber.js": "^7.2.0",
     "body-parser": "1.19.0",
+    "bunyan": "1.8.12",
+    "bunyan-gke-stackdriver": "0.1.2",
     "debug": "^4.1.1",
     "dotenv": "8.0.0",
     "eth-lib": "^0.2.8",
@@ -40,9 +42,11 @@
     "web3": "1.0.0-beta.37",
     "express": "4.17.1",
     "express-rate-limit": "5.0.0",
+    "express-request-id": "1.4.1",
     "mysql2": "2.0.0-alpha1",
     "pg": "7.12.1",
     "pg-hstore": "2.3.3",
+    "prom-client": "11.2.0",
     "sequelize": "5.13.1",
     "sequelize-cli": "5.5.0",
     "sqlite3": "4.0.9",
@@ -51,6 +55,7 @@
   },
   "devDependencies": {
     "@celo/protocol": "1.0.0",
+    "@types/bunyan": "1.8.4",
     "@types/dotenv": "4.0.3",
     "@types/debug": "^4.1.5",
     "@types/express-rate-limit": "2.9.3",

packages/attestation-service/src/db.ts

@@ -1,13 +1,17 @@
 import { ContractKit, newKit } from '@celo/contractkit'
 import { FindOptions, Sequelize } from 'sequelize'
 import { fetchEnv } from './env'
+import { rootLogger } from './logger'
 import Attestation, { AttestationModel, AttestationStatic } from './models/attestation'
 
 export let sequelize: Sequelize | undefined
 
 export function initializeDB() {
   if (sequelize === undefined) {
-    sequelize = new Sequelize(fetchEnv('DATABASE_URL'))
+    sequelize = new Sequelize(fetchEnv('DATABASE_URL'), {
+      logging: (msg: string, sequelizeLogArgs: any) =>
+        rootLogger.debug({ sequelizeLogArgs, component: 'sequelize' }, msg),
+    })
     return sequelize.authenticate() as Promise<void>
   }
   return Promise.resolve()

packages/attestation-service/src/env.ts

@@ -1,11 +1,19 @@
+import * as dotenv from 'dotenv'
+
+if (process.env.CONFIG) {
+  dotenv.config({ path: process.env.CONFIG })
+}
+
 export function fetchEnv(name: string): string {
-  if (process.env[name] === undefined) {
+  if (process.env[name] === undefined || process.env[name] === '') {
     console.error(`ENV var '${name}' was not defined`)
     throw new Error(`ENV var '${name}' was not defined`)
   }
   return process.env[name] as string
 }
 
 export function fetchEnvOrDefault(name: string, defaultValue: string): string {
-  return process.env[name] === undefined ? defaultValue : (process.env[name] as string)
+  return process.env[name] === undefined || process.env[name] === ''
+    ? defaultValue
+    : (process.env[name] as string)
 }

packages/attestation-service/src/index.ts

@@ -1,38 +1,39 @@
-import * as dotenv from 'dotenv'
 import express from 'express'
 import RateLimiter from 'express-rate-limit'
+import requestIdMiddleware from 'express-request-id'
+import * as PromClient from 'prom-client'
 import { initializeDB, initializeKit } from './db'
-import { createValidatedHandler } from './request'
+import { rootLogger } from './logger'
+import { createValidatedHandler, loggerMiddleware } from './request'
 import {
   AttestationRequestType,
   getAttestationKey,
   handleAttestationRequest,
 } from './requestHandlers/attestation'
 import { handleStatusRequest, StatusRequestType } from './requestHandlers/status'
 import { initializeSmsProviders } from './sms'
-async function init() {
-  console.info(process.env.CONFIG)
-  if (process.env.CONFIG) {
-    dotenv.config({ path: process.env.CONFIG })
-  }
 
+async function init() {
   await initializeDB()
   await initializeKit()
   // TODO: Validate that the attestation key has been authorized by the account
   getAttestationKey()
   await initializeSmsProviders()
 
   const app = express()
-  app.use(express.json())
+  app.use([express.json(), requestIdMiddleware(), loggerMiddleware])
   const port = process.env.PORT || 3000
-  app.listen(port, () => console.log(`Server running on ${port}!`))
+  app.listen(port, () => rootLogger.info({ port }, 'Attestation Service started'))
 
   const rateLimiter = new RateLimiter({
     windowMs: 5 * 60 * 100, // 5 minutes
     max: 50,
     // @ts-ignore
     message: { status: false, error: 'Too many requests, please try again later' },
   })
+  app.get('/metrics', (_req, res) => {
+    res.send(PromClient.register.metrics())
+  })
   app.get('/status', rateLimiter, createValidatedHandler(StatusRequestType, handleStatusRequest))
   app.post(
     '/attestations',
@@ -41,7 +42,6 @@ async function init() {
 }
 
 init().catch((err) => {
-  console.error(`Error occurred while running server, exiting ....`)
-  console.error(err)
+  rootLogger.error({ err })
   process.exit(1)
 })

packages/attestation-service/src/logger.ts

@@ -0,0 +1,17 @@
+import Logger, { createLogger, levelFromName, LogLevelString, stdSerializers } from 'bunyan'
+import { createStream } from 'bunyan-gke-stackdriver'
+import { fetchEnvOrDefault } from './env'
+
+const logLevel = fetchEnvOrDefault('LOG_LEVEL', 'info') as LogLevelString
+const logFormat = fetchEnvOrDefault('LOG_FORMAT', 'default')
+
+const stream =
+  logFormat === 'stackdriver'
+    ? createStream(levelFromName[logLevel])
+    : { stream: process.stdout, level: logLevel }
+
+export const rootLogger: Logger = createLogger({
+  name: 'attestation-service',
+  serializers: stdSerializers,
+  streams: [stream],
+})

packages/attestation-service/src/metrics.ts

@@ -0,0 +1,45 @@
+import { Counter } from 'prom-client'
+
+export const Counters = {
+  attestationRequestsTotal: new Counter({
+    name: 'attestation_requests_total',
+    help: 'Counter for the number of attestation requests',
+  }),
+  attestationRequestsAlreadySent: new Counter({
+    name: 'attestation_requests_already_sent',
+    help: 'Counter for the number of attestation requests that were already sent',
+  }),
+  attestationRequestsWrongIssuer: new Counter({
+    name: 'attestation_requests_wrong_issuer',
+    help: 'Counter for the number of attestation requests that specified the wrong issuer',
+  }),
+  attestationRequestsWOIncompleteAttestation: new Counter({
+    name: 'attestation_requests_without_incomplete_attestation',
+    help:
+      'Counter for the number of attestation requests for which no incomplete attestations could be found',
+  }),
+  attestationRequestsValid: new Counter({
+    name: 'attestation_requests_valid',
+    help: 'Counter for the number of requests involving valid attestation requests',
+  }),
+  attestationRequestsAttestationErrors: new Counter({
+    name: 'attestation_requests_attestation_errors',
+    help: 'Counter for the number of requests for which producing the attestation failed',
+  }),
+  attestationRequestsUnableToServe: new Counter({
+    name: 'attestation_requests_unable_to_serve',
+    help: 'Counter for the number of requests that could not be served',
+  }),
+  attestationRequestsSentSms: new Counter({
+    name: 'attestation_requests_sent_sms',
+    help: 'Counter for the number of sms sent',
+  }),
+  attestationRequestsFailedToSendSms: new Counter({
+    name: 'attestation_requests_failed_to_send_sms',
+    help: 'Counter for the number of sms that failed to send',
+  }),
+  attestationRequestUnexpectedErrors: new Counter({
+    name: 'attestation_requests_unexpected_errors',
+    help: 'Counter for the number of unexpected errrors',
+  }),
+}

packages/attestation-service/src/request.ts

@@ -1,29 +1,36 @@
+import Logger from 'bunyan'
 import express from 'express'
 import { isLeft } from 'fp-ts/lib/Either'
 import * as t from 'io-ts'
+import { rootLogger } from './logger'
 
 export enum ErrorMessages {
   UNKNOWN_ERROR = 'Something went wrong',
 }
 
-export function catchAsyncErrorHandler<T>(
-  handler: (req: express.Request, res: express.Response) => Promise<T>
-) {
-  return async (req: express.Request, res: express.Response) => {
+export function asyncHandler<T>(handler: (req: express.Request, res: Response) => Promise<T>) {
+  return (req: express.Request, res: Response) => {
+    const handleUnknownError = (error: Error) => {
+      if (res.locals.logger) {
+        res.locals.logger.error(error)
+      }
+      respondWithError(res, 500, ErrorMessages.UNKNOWN_ERROR)
+    }
     try {
-      return handler(req, res)
+      handler(req, res)
+        .then(() => res.locals.logger.info({ res }))
+        .catch(handleUnknownError)
     } catch (error) {
-      console.error(error)
-      respondWithError(res, 500, ErrorMessages.UNKNOWN_ERROR)
+      handleUnknownError(error)
     }
   }
 }
 
 export function createValidatedHandler<T>(
   requestType: t.Type<T>,
-  handler: (req: express.Request, res: express.Response, parsedRequest: T) => Promise<void>
+  handler: (req: express.Request, res: Response, parsedRequest: T) => Promise<void>
 ) {
-  return catchAsyncErrorHandler(async (req: express.Request, res: express.Response) => {
+  return asyncHandler(async (req: express.Request, res: Response) => {
     const parsedRequest = requestType.decode({ ...req.query, ...req.body })
     if (isLeft(parsedRequest)) {
       res.status(422).json({
@@ -64,3 +71,22 @@ function serializeErrors(errors: t.Errors) {
 export function respondWithError(res: express.Response, statusCode: number, error: string) {
   res.status(statusCode).json({ success: false, error })
 }
+
+export type Response = Omit<express.Response, 'locals'> & {
+  locals: { logger: Logger } & Omit<any, 'logger'>
+}
+
+export function loggerMiddleware(
+  req: express.Request,
+  res: express.Response,
+  next: express.NextFunction
+) {
+  const requestLogger = rootLogger.child({
+    // @ts-ignore express-request-id adds this
+    req_id: req.id,
+  })
+
+  res.locals.logger = requestLogger
+  requestLogger.info({ req })
+  next()
+}