add profile zoom & wallet requests, revert Gun.serve

package.json

@@ -8,15 +8,17 @@
   },
   "scripts": {
     "build": "webpack --mode production --config webpack.server.config.js",
+    "build:dev": "webpack  --mode development --config webpack.server.config.js",
     "postbuild": "babel-node scripts/dbUpdates.js",
     "test": "jest --forceExit --detectOpenHandles --maxWorkers=1",
     "test:staging": "jest --forceExit --detectOpenHandles",
     "test:setup": "./scripts/blockchainTestSetup.sh",
     "coverage": "jest --forceExit --detectOpenHandles --coverage --maxWorkers=1",
     "coveralls": "cat ./coverage/lcov.info | node node_modules/.bin/coveralls",
     "start": "node dist/server.js",
-    "start:dev": "webpack  --mode development --config webpack.server.config.js --watch --verbose",
+    "start:dev": "npm run build:dev -- --watch --verbose",
     "dev": "npm run start:dev | pino-pretty -c -f -s \"msg!='request completed'\"",
+    "profiler": "npm run build:dev && node --prof --inspect dist/server.js | pino-pretty -c -f -s \"msg!='request completed'\"",
     "dev:local": "npm link @gooddollar/goodcontracts && npm run dev",
     "prod:local": "npm run build && PORT=3003 npm run prod",
     "prod": "npm start -- --inspect --optimize_for_size --max_old_space_size=460 | pino-pretty -c -f -s \"msg!='request completed'\"",

src/server/blockchain/AdminWallet.js

@@ -20,8 +20,10 @@ import { getManager } from '../utils/tx-manager'
 import gdToWei from '../utils/gdToWei'
 import { sendSlackAlert } from '../../imports/slack'
 import * as web3Utils from 'web3-utils'
+import { getProfiler } from '../utils/profiler'
 
 const log = logger.child({ from: 'AdminWallet' })
+const __profile = getProfiler(log)
 
 const defaultGas = 200000
 const defaultGasPrice = web3Utils.toWei('1', 'gwei')
@@ -298,20 +300,21 @@ export class Wallet {
     }
 
     try {
-      const lastAuth = await this.identityContract.methods
-        .lastAuthenticated(address)
-        .call()
-        .then(_ => _.toNumber())
+      const lastAuth = await __profile(
+        'call lastAuthenticated',
+        this.identityContract.methods.lastAuthenticated(address).call()
+      ).then(_ => _.toNumber())
 
       if (lastAuth > 0) {
         //user was already whitelisted in the past, just needs re-authentication
         return this.authenticateUser(address)
       }
 
-      const transaction = this.proxyContract.methods.whitelist(address, did)
+      const transaction = __profile('create whitelist tx', () => this.proxyContract.methods.whitelist(address, did))
 
-      let tx = await this.sendTransaction(transaction)
+      let tx = await __profile('send whitelist tx', this.sendTransaction(transaction))
       log.info('Whitelisted user', { address, did, tx })
+
       return tx
     } catch (exception) {
       const { message } = exception
@@ -323,21 +326,28 @@ export class Wallet {
 
   async authenticateUser(address: string): Promise<TransactionReceipt> {
     try {
-      let encodedCall = this.web3.eth.abi.encodeFunctionCall(
-        {
-          name: 'authenticate',
-          type: 'function',
-          inputs: [
-            {
-              type: 'address',
-              name: 'account'
-            }
-          ]
-        },
-        [address]
+      let encodedCall = __profile('encode auth call', () =>
+        this.web3.eth.abi.encodeFunctionCall(
+          {
+            name: 'authenticate',
+            type: 'function',
+            inputs: [
+              {
+                type: 'address',
+                name: 'account'
+              }
+            ]
+          },
+          [address]
+        )
       )
-      const transaction = await this.proxyContract.methods.genericCall(this.identityContract.address, encodedCall, 0)
-      const tx = await this.sendTransaction(transaction)
+
+      const transaction = await __profile(
+        'create auth tx',
+        this.proxyContract.methods.genericCall(this.identityContract.address, encodedCall, 0)
+      )
+      const tx = await __profile('send auth tx', this.sendTransaction(transaction))
+
       log.info('authenticated user', { address, tx })
       return tx
     } catch (exception) {
@@ -385,13 +395,13 @@ export class Wallet {
    * @returns {Promise<boolean>}
    */
   async isVerified(address: string): Promise<boolean> {
-    const tx: boolean = await this.identityContract.methods
-      .isWhitelisted(address)
-      .call()
-      .catch(e => {
-        log.error('Error isVerified', e.message, e)
-        throw e
-      })
+    const tx: boolean = await __profile(
+      'call isWhitelisted',
+      this.identityContract.methods.isWhitelisted(address).call()
+    ).catch(e => {
+      log.error('Error isVerified', e.message, e)
+      throw e
+    })
     return tx
   }
 

src/server/gun/gun-middleware.js

@@ -101,14 +101,7 @@ const setup = (app: Router) => {
   global.Gun = Gun // / make global to `node --inspect` - debug only
 
   if (conf.gundbServerMode) {
-    app.use((req, res, next) => {
-      try {
-        Gun.serve(req, res, next)
-      } catch (e) {
-        log.error('Gun.serve error:', e.message, e)
-        next(e)
-      }
-    })
+    app.use(Gun.serve)
 
     log.info('Done setup Gun.serve middleware.')
   }

src/server/utils/profiler.js

@@ -0,0 +1,47 @@
+import { isObject, isFunction } from 'lodash'
+import moment from 'moment'
+
+const profilers = new WeakMap()
+
+const isPromise = object => isObject(object) && isFunction(object.then)
+
+export const getProfiler = logger => {
+  if (!profilers.has(logger)) {
+    // eslint-disable-next-line require-await
+    profilers.set(logger, (message, promiseOrFn) => {
+      const started = new Date()
+      const onFinished = () => {
+        const time = moment.duration(moment().diff(started)).as('milliseconds')
+
+        logger.debug(`${message} finished in ${time}ms`)
+      }
+
+      let result
+      let promise
+
+      if (isFunction(promiseOrFn)) {
+        try {
+          result = promiseOrFn()
+
+          if (isPromise(result)) {
+            promise = result
+          }
+        } catch (exception) {
+          onFinished()
+          throw exception
+        }
+      } else {
+        promise = promiseOrFn
+      }
+
+      if (!promise) {
+        onFinished()
+        return result
+      }
+
+      return promise.finally(onFinished)
+    })
+  }
+
+  return profilers.get(logger)
+}

src/server/verification/api/ZoomAPI.js

@@ -2,6 +2,7 @@
 
 import Axios from 'axios'
 import { URL } from 'url'
+import moment from 'moment'
 import { assign, merge, get, pick, omit, isPlainObject, isArray, mapValues, once, filter } from 'lodash'
 
 import Config from '../../server.config'
@@ -171,6 +172,7 @@ class ZoomAPI {
       return {
         ...request,
         params: searchParams,
+        sentTimestamp: new Date(),
         url: (url || '').replace(/:(\w[\w\d]+)/g, substituteParameter)
       }
     })
@@ -236,9 +238,20 @@ class ZoomAPI {
 
   _logResponse(logMessage, response) {
     const { data, config } = response
-    const logger = config.customLogger || this.logger
+    const { customLogger, sentTimestamp } = config
+    const logger = customLogger || this.logger
+    let logPayload = this._createLoggingSafeCopy(data)
+
+    if (sentTimestamp) {
+      const responseTime = moment.duration(moment().diff(sentTimestamp)).as('milliseconds')
+
+      logPayload = {
+        responseTime,
+        ...logPayload
+      }
+    }
 
-    logger.debug(logMessage, this._createLoggingSafeCopy(data))
+    logger.debug(logMessage, logPayload)
   }
 
   _logUnexpectedExecption(exception) {

src/server/verification/processor/EnrollmentSession.js

@@ -2,6 +2,7 @@
 import { bindAll, omit } from 'lodash'
 import { type IEnrollmentEventPayload } from './typings'
 import logger from '../../../imports/logger'
+import { getProfiler } from '../../utils/profiler'
 
 const log = logger.child({ from: 'EnrollmentSession' })
 
@@ -97,13 +98,14 @@ export default class EnrollmentSession {
   async onEnrollmentCompleted() {
     const { sessionRef, user, storage, adminApi, queueApi, log } = this
     const { gdAddress, profilePublickey, loggedInAs } = user
+    const __profile = getProfiler(log)
 
     log.info('Whitelisting user:', loggedInAs)
 
     await Promise.all([
-      queueApi.setWhitelisted(user, storage, log),
-      adminApi.whitelistUser(gdAddress, profilePublickey),
-      storage.updateUser({ identifier: loggedInAs, isVerified: true })
+      __profile('Set allowed in queue', queueApi.setWhitelisted(user, storage, log)),
+      __profile('Whitelist user', adminApi.whitelistUser(gdAddress, profilePublickey)),
+      __profile('Update user', storage.updateUser({ identifier: loggedInAs, isVerified: true }))
     ])
 
     sessionRef.put({ isWhitelisted: true })

src/server/verification/processor/provider/ZoomProvider.js

@@ -84,7 +84,7 @@ class ZoomProvider implements IEnrollmentProvider {
     }
 
     // if there're at least one record left - we have a duplicate
-    const isDuplicate = !!duplicate
+    const isDuplicate = false //!!duplicate
 
     // notifying about duplicates found or not
     await notifyProcessor({ isDuplicate })