Odis tracing 18

packages/phone-number-privacy/common/package.json

@@ -30,7 +30,14 @@
     "dotenv": "^8.2.0",
     "elliptic": "^6.5.4",
     "io-ts": "2.0.1",
-    "is-base64": "^1.1.0"
+    "is-base64": "^1.1.0",
+    "@opentelemetry/api": "^1.4.1",
+    "@opentelemetry/auto-instrumentations-node": "^0.38.0",
+    "@opentelemetry/propagator-ot-trace": "^0.27.0",
+    "@opentelemetry/sdk-metrics": "^1.15.1",
+    "@opentelemetry/sdk-node": "^0.41.1",
+    "@opentelemetry/semantic-conventions": "^1.15.1",
+    "@opentelemetry/sdk-trace-web": "^1.15.1"
   },
   "devDependencies": {
     "@celo/poprf": "^0.1.9",

packages/phone-number-privacy/common/src/utils/authentication.ts

@@ -16,6 +16,9 @@ import {
 } from '../interfaces'
 import { FULL_NODE_TIMEOUT_IN_MS, RETRY_COUNT, RETRY_DELAY_IN_MS } from './constants'
 
+import opentelemetry, { SpanStatusCode } from '@opentelemetry/api'
+const tracer = opentelemetry.trace.getTracer('signer-tracer')
+
 /*
  * Confirms that user is who they say they are and throws error on failure to confirm.
  * Authorization header should contain the EC signed body
@@ -30,60 +33,94 @@ export async function authenticateUser<R extends PhoneNumberPrivacyRequest>(
   retryCount: number = RETRY_COUNT,
   retryDelay: number = RETRY_DELAY_IN_MS
 ): Promise<boolean> {
-  logger.debug('Authenticating user')
-
-  // https://tools.ietf.org/html/rfc7235#section-4.2
-  const messageSignature = request.get('Authorization')
-  const message = JSON.stringify(request.body)
-  const signer = request.body.account
-  const authMethod = request.body.authenticationMethod
+  return tracer.startActiveSpan('Authentication - authenticateUser', async (span) => {
+    logger.debug('Authenticating user')
+    span.addEvent('Authenticating user')
 
-  if (!messageSignature || !signer) {
-    return false
-  }
+    // https://tools.ietf.org/html/rfc7235#section-4.2
+    const messageSignature = request.get('Authorization')
+    const message = JSON.stringify(request.body)
+    const signer = request.body.account
+    const authMethod = request.body.authenticationMethod
 
-  if (authMethod && authMethod === AuthenticationMethod.ENCRYPTION_KEY) {
-    let registeredEncryptionKey
-    try {
-      registeredEncryptionKey = await getDataEncryptionKey(
-        signer,
-        contractKit,
-        logger,
-        timeoutMs,
-        retryCount,
-        retryDelay
-      )
-    } catch (err) {
-      // getDataEncryptionKey should only throw if there is a full-node connection issue.
-      // That is, it does not throw if the DEK is undefined or invalid
-      const failureStatus = shouldFailOpen ? ErrorMessage.FAILING_OPEN : ErrorMessage.FAILING_CLOSED
-      logger.error({
-        err,
-        warning: ErrorMessage.FAILURE_TO_GET_DEK,
-        failureStatus,
+    if (!messageSignature || !signer) {
+      span.addEvent('No messageSignature or signer')
+      span.setStatus({
+        code: SpanStatusCode.ERROR,
+        message: 'No messageSignature or signer',
       })
-      warnings.push(ErrorMessage.FAILURE_TO_GET_DEK, failureStatus)
-      return shouldFailOpen
-    }
-    if (!registeredEncryptionKey) {
-      logger.warn({ account: signer }, 'Account does not have registered encryption key')
+      span.end()
       return false
-    } else {
-      logger.info({ dek: registeredEncryptionKey, account: signer }, 'Found DEK for account')
-      if (verifyDEKSignature(message, messageSignature, registeredEncryptionKey, logger)) {
-        return true
+    }
+
+    if (authMethod && authMethod === AuthenticationMethod.ENCRYPTION_KEY) {
+      span.addEvent('Authenticating user with encryption key')
+      let registeredEncryptionKey
+      try {
+        span.addEvent('Getting data emcryption key')
+        registeredEncryptionKey = await getDataEncryptionKey(
+          signer,
+          contractKit,
+          logger,
+          timeoutMs,
+          retryCount,
+          retryDelay
+        )
+      } catch (err) {
+        // getDataEncryptionKey should only throw if there is a full-node connection issue.
+        // That is, it does not throw if the DEK is undefined or invalid
+        const failureStatus = shouldFailOpen
+          ? ErrorMessage.FAILING_OPEN
+          : ErrorMessage.FAILING_CLOSED
+        logger.error({
+          err,
+          warning: ErrorMessage.FAILURE_TO_GET_DEK,
+          failureStatus,
+        })
+        warnings.push(ErrorMessage.FAILURE_TO_GET_DEK, failureStatus)
+        span.addEvent('Error with full-node connection issue')
+        span.setStatus({
+          code: SpanStatusCode.ERROR,
+          message: ErrorMessage.FAILURE_TO_GET_DEK + failureStatus,
+        })
+        span.end()
+        return shouldFailOpen
+      }
+      if (!registeredEncryptionKey) {
+        logger.warn({ account: signer }, 'Account does not have registered encryption key')
+        span.addEvent('Account does not have registered encryption key')
+        span.setStatus({
+          code: SpanStatusCode.ERROR,
+          message: 'Account does not have registered encryption key',
+        })
+        span.end()
+        return false
+      } else {
+        span.addEvent('Verifying with DEK')
+        logger.info({ dek: registeredEncryptionKey, account: signer }, 'Found DEK for account')
+        if (verifyDEKSignature(message, messageSignature, registeredEncryptionKey, logger)) {
+          span.addEvent('DEK verification OK')
+          span.setStatus({
+            code: SpanStatusCode.OK,
+            message: 'DEK verifycation OK',
+          })
+          span.end()
+          return true
+        }
       }
     }
-  }
 
-  // Fallback to previous signing pattern
-  logger.info(
-    { account: signer, message, messageSignature },
-    'Message was not authenticated with DEK, attempting to authenticate using wallet key'
-  )
-  // TODO This uses signature utils, why doesn't DEK authentication?
-  // (https://github.com/celo-org/celo-monorepo/issues/9803)
-  return verifySignature(message, messageSignature, signer)
+    // Fallback to previous signing pattern
+    logger.info(
+      { account: signer, message, messageSignature },
+      'Message was not authenticated with DEK, attempting to authenticate using wallet key'
+    )
+    // TODO This uses signature utils, why doesn't DEK authentication?
+    // (https://github.com/celo-org/celo-monorepo/issues/9803)
+    span.addEvent('Verifying with wallet key')
+    span.end()
+    return verifySignature(message, messageSignature, signer)
+  })
 }
 
 export function getMessageDigest(message: string) {

packages/phone-number-privacy/signer/package.json

@@ -5,9 +5,11 @@
   "author": "Celo",
   "license": "Apache-2.0",
   "main": "dist/index.js",
+  "types": "dist/index.d.ts",
   "scripts": {
     "start": "yarn build && node -r dotenv/config dist/index.js",
     "start:docker": "yarn build && node dist/index.js",
+    "start:docker:tracing": "yarn build && node --require ./dist/tracing.js dist/index.js",
     "clean": "tsc -b . --clean",
     "build": "tsc -b .",
     "lint": "tslint --project .",
@@ -44,6 +46,13 @@
     "@celo/utils": "^4.1.1-dev",
     "@celo/wallet-hsm-azure": "^4.1.1-dev",
     "@google-cloud/secret-manager": "3.0.0",
+    "@opentelemetry/api": "^1.4.1",
+    "@opentelemetry/auto-instrumentations-node": "^0.38.0",
+    "@opentelemetry/propagator-ot-trace": "^0.27.0",
+    "@opentelemetry/sdk-metrics": "^1.15.1",
+    "@opentelemetry/sdk-node": "^0.41.1",
+    "@opentelemetry/semantic-conventions": "^1.15.1",
+    "@opentelemetry/sdk-trace-web": "^1.15.1",
     "@types/bunyan": "^1.8.8",
     "aws-sdk": "^2.705.0",
     "blind-threshold-bls": "https://github.com/celo-org/blind-threshold-bls-wasm#e1e2f8a",
@@ -68,4 +77,4 @@
   "engines": {
     "node": ">=10"
   }
-}
+}

packages/phone-number-privacy/signer/src/common/controller.ts

@@ -9,6 +9,9 @@ import { Request, Response } from 'express'
 import { Action } from './action'
 import { Counters, Histograms, meter } from './metrics'
 
+import opentelemetry from '@opentelemetry/api'
+const tracer = opentelemetry.trace.getTracer('signer-tracer')
+
 export class Controller<R extends OdisRequest> {
   constructor(readonly action: Action<R>) {}
 
@@ -21,11 +24,19 @@ export class Controller<R extends OdisRequest> {
     const timeoutError = Symbol()
     await meter(
       async () => {
-        const session = await this.action.io.init(request, response)
-        // Init returns a response to the user internally.
-        if (session) {
-          await this.action.perform(session, timeoutError)
-        }
+        tracer
+          .startActiveSpan('Controller - handle', async (span) => {
+            span.addEvent('Calling init')
+            const session = await this.action.io.init(request, response)
+            // Init returns a response to the user internally.
+            if (session) {
+              span.addEvent('Calling perform')
+              await this.action.perform(session, timeoutError)
+            }
+            span.end()
+          })
+          .then(() => response.locals.logger.debug('Span then block'))
+          .catch(() => response.locals.logger.debug('Span catch block'))
       },
       [],
       (err: any) => {

packages/phone-number-privacy/signer/src/common/io.ts

@@ -11,6 +11,10 @@ import Logger from 'bunyan'
 import { Request, Response } from 'express'
 import { Session } from './action'
 
+import opentelemetry, { SpanStatusCode } from '@opentelemetry/api'
+import { SemanticAttributes } from '@opentelemetry/semantic-conventions'
+const tracer = opentelemetry.trace.getTracer('signer-tracer')
+
 export abstract class IO<R extends OdisRequest> {
   abstract readonly endpoint: SignerEndpoint
 
@@ -46,14 +50,36 @@ export abstract class IO<R extends OdisRequest> {
     request: Request<{}, {}, unknown>,
     response: Response<OdisResponse<R>>
   ): request is Request<{}, {}, R> {
-    if (!this.enabled) {
-      this.sendFailure(WarningMessage.API_UNAVAILABLE, 503, response)
-      return false
-    }
-    if (!this.validate(request)) {
-      this.sendFailure(WarningMessage.INVALID_INPUT, 400, response)
-      return false
-    }
-    return true
+    return tracer.startActiveSpan('CommonIO - inputChecks', (span) => {
+      if (!this.enabled) {
+        span.addEvent('Error calling enabled')
+        span.setStatus({
+          code: SpanStatusCode.ERROR,
+          message: WarningMessage.API_UNAVAILABLE,
+        })
+        span.setAttribute(SemanticAttributes.HTTP_STATUS_CODE, 503)
+        this.sendFailure(WarningMessage.API_UNAVAILABLE, 503, response)
+        span.end()
+        return false
+      }
+      if (!this.validate(request)) {
+        span.addEvent('Error calling validate')
+        span.setStatus({
+          code: SpanStatusCode.ERROR,
+          message: WarningMessage.INVALID_INPUT,
+        })
+        span.setAttribute(SemanticAttributes.HTTP_STATUS_CODE, 400)
+        this.sendFailure(WarningMessage.INVALID_INPUT, 400, response)
+        span.end()
+        return false
+      }
+      span.addEvent('Correctly called inputChecks')
+      span.setStatus({
+        code: SpanStatusCode.OK,
+        message: response.statusMessage,
+      })
+      span.end()
+      return true
+    })
   }
 }