Fix a bug whereby too many node connections are created under high lo…

…ad leading to 429s (#522)

* Fix a bug whereby too many node connections are created under high load leading to 429s

Adds a test for creating 500 demandAs in parrallel and then fixs exposed issues. Broadly speaking this is caused by each controller being instantiated for each request. This was then making a ChainNode per request and thus a polkadot instance. I've made `ChainNode` a singleton now to avoid this.

In order to make tests perform sensibly I've also improved the way we were polling for state changes

* Add reflect-metadata'

* Fix container reset in test

* Updating version to 3.1.0

* Fix linting issues

* Fix tests import reflect-metadata'

---------

Co-authored-by: dc-autobot[bot] <181364585+dc-autobot[bot]@users.noreply.github.com>

package.json

@@ -1,6 +1,6 @@
 {
   "name": "@digicatapult/sqnc-matchmaker-api",
-  "version": "3.0.136",
+  "version": "3.1.0",
   "description": "An OpenAPI Matchmaking API service for SQNC",
   "main": "src/index.ts",
   "type": "module",
@@ -75,6 +75,7 @@
     "@digicatapult/tsoa-oauth-express": "^0.1.69",
     "@polkadot/api": "^14.3.1",
     "@tsoa/runtime": "^6.5.1",
+    "async-mutex": "^0.5.0",
     "base-x": "^5.0.0",
     "body-parser": "^1.20.3",
     "cors": "^2.8.5",
@@ -86,6 +87,7 @@
     "multer": "^1.4.5-lts.1",
     "pg": "^8.13.1",
     "pino": "^9.5.0",
+    "reflect-metadata": "^0.2.2",
     "swagger-ui-express": "^5.0.1",
     "tsoa": "^6.5.1",
     "tsyringe": "^4.8.0",

src/authentication.ts

@@ -14,7 +14,7 @@ const exampleOptions: AuthOptions = {
     const scopes = ((decoded as jwt.JwtPayload).scopes as string) || ''
     return scopes.split(' ')
   },
-  tryRefreshTokens: (_req: express.Request) => Promise.resolve(false),
+  tryRefreshTokens: () => Promise.resolve(false),
 }
 
 export const expressAuthentication = mkExpressAuthentication(exampleOptions)

src/controllers/v1/_common/demand.ts

@@ -17,32 +17,27 @@ import { BadRequest, NotFound } from '../../../lib/error-handler/index.js'
 import { TransactionResponse, TransactionType } from '../../../models/transaction.js'
 import { demandCommentCreate, demandCreate } from '../../../lib/payload.js'
 import ChainNode from '../../../lib/chainNode.js'
-import env from '../../../env.js'
 import { parseDateParam } from '../../../lib/utils/queryParams.js'
 import Identity from '../../../lib/services/identity.js'
 import { getAuthorization } from '../../../lib/utils/shared.js'
 
+let self: { address: string; alias: string } | null = null
 export class DemandController extends Controller {
   demandType: 'demandA' | 'demandB'
   dbDemandSubtype: 'demand_a' | 'demand_b'
   log: Logger
   db: Database
-  node: ChainNode
-  private identity: Identity
 
-  constructor(demandType: 'demandA' | 'demandB', identity: Identity) {
+  constructor(
+    demandType: 'demandA' | 'demandB',
+    private identity: Identity,
+    private node: ChainNode
+  ) {
     super()
     this.demandType = demandType
     this.dbDemandSubtype = demandType === 'demandA' ? 'demand_a' : 'demand_b'
     this.log = logger.child({ controller: `/${this.demandType}` })
     this.db = new Database()
-    this.node = new ChainNode({
-      host: env.NODE_HOST,
-      port: env.NODE_PORT,
-      logger,
-      userUri: env.USER_URI,
-    })
-    this.identity = identity
   }
 
   public async createDemand(req: express.Request, { parametersAttachmentId }: DemandRequest): Promise<DemandResponse> {
@@ -52,7 +47,8 @@ export class DemandController extends Controller {
       throw new BadRequest('Attachment not found')
     }
 
-    const res = await this.identity.getMemberBySelf(getAuthorization(req))
+    const res = self || (await this.identity.getMemberBySelf(getAuthorization(req)))
+    self = res
     const selfAddress = res.address
     const selfAlias = res.alias
 

src/controllers/v1/attachment/index.ts

@@ -161,7 +161,8 @@ export class attachment extends Controller {
             const json = JSON.parse(blobBuffer.toString())
             return json
           } catch (err) {
-            this.log.warn(`Unable to parse json file for attachment ${id}`)
+            this.log.warn('Unable to parse json file for attachment %s', id)
+            this.log.debug('Parse error: %s', err instanceof Error ? err.message : 'unknown')
             return this.octetResponse(blobBuffer, filename)
           }
         }

src/controllers/v1/demandA/index.ts

@@ -27,14 +27,15 @@ import { BadRequest, NotFound } from '../../../lib/error-handler/index.js'
 import { TransactionResponse } from '../../../models/transaction.js'
 import { DemandController } from '../_common/demand.js'
 import Identity from '../../../lib/services/identity.js'
+import ChainNode from '../../../lib/chainNode.js'
 
 @Route('v1/demandA')
 @injectable()
 @Tags('demandA')
 @Security('oauth2')
 export class DemandAController extends DemandController {
-  constructor(identity: Identity) {
-    super('demandA', identity)
+  constructor(identity: Identity, node: ChainNode) {
+    super('demandA', identity, node)
   }
 
   /**

src/controllers/v1/demandB/index.ts

@@ -27,14 +27,15 @@ import { BadRequest, NotFound } from '../../../lib/error-handler/index.js'
 import { TransactionResponse } from '../../../models/transaction.js'
 import { DemandController } from '../_common/demand.js'
 import Identity from '../../../lib/services/identity.js'
+import ChainNode from '../../../lib/chainNode.js'
 
 @Route('v1/demandB')
 @injectable()
 @Tags('demandB')
 @Security('oauth2')
 export class DemandBController extends DemandController {
-  constructor(identity: Identity) {
-    super('demandB', identity)
+  constructor(identity: Identity, node: ChainNode) {
+    super('demandB', identity, node)
   }
 
   /**

src/controllers/v1/match2/index.ts

@@ -42,7 +42,6 @@ import {
   rematch2AcceptFinal,
 } from '../../../lib/payload.js'
 import ChainNode from '../../../lib/chainNode.js'
-import env from '../../../env.js'
 import { parseDateParam } from '../../../lib/utils/queryParams.js'
 import { getAuthorization } from '../../../lib/utils/shared.js'
 
@@ -53,19 +52,14 @@ import { getAuthorization } from '../../../lib/utils/shared.js'
 export class Match2Controller extends Controller {
   log: Logger
   db: Database
-  node: ChainNode
 
-  constructor(private identity: Identity) {
+  constructor(
+    private identity: Identity,
+    private node: ChainNode
+  ) {
     super()
     this.log = logger.child({ controller: '/match2' })
     this.db = new Database()
-    this.node = new ChainNode({
-      host: env.NODE_HOST,
-      port: env.NODE_PORT,
-      logger,
-      userUri: env.USER_URI,
-    })
-    this.identity = identity
   }
 
   /**

src/env.ts

@@ -1,13 +1,14 @@
 import * as envalid from 'envalid'
 import dotenv from 'dotenv'
+import { container } from 'tsyringe'
 
 if (process.env.NODE_ENV === 'test') {
   dotenv.config({ path: 'test/test.env' })
 } else {
   dotenv.config()
 }
 
-export default envalid.cleanEnv(process.env, {
+const env = envalid.cleanEnv(process.env, {
   PORT: envalid.port({ default: 3000 }),
   LOG_LEVEL: envalid.str({ default: 'info', devDefault: 'debug' }),
   DB_HOST: envalid.str({ devDefault: 'localhost' }),
@@ -42,3 +43,12 @@ export default envalid.cleanEnv(process.env, {
     default: '/certs',
   }),
 })
+
+export default env
+
+export const EnvToken = Symbol('Env')
+export type Env = typeof env
+
+container.register<Env>(EnvToken, {
+  useValue: env,
+})

src/index.ts

@@ -1,4 +1,7 @@
+import 'reflect-metadata'
+
 import { Express } from 'express'
+import { container } from 'tsyringe'
 
 import Indexer from './lib/indexer/index.js'
 import ChainNode from './lib/chainNode.js'
@@ -10,12 +13,7 @@ import { logger } from './lib/logger.js'
   const app: Express = await Server()
 
   if (env.ENABLE_INDEXER) {
-    const node = new ChainNode({
-      host: env.NODE_HOST,
-      port: env.NODE_PORT,
-      logger,
-      userUri: env.USER_URI,
-    })
+    const node = container.resolve(ChainNode)
 
     const indexer = new Indexer({ db: new Database(), logger, node })
     await indexer.start()

src/ioc.ts

@@ -1,8 +1,18 @@
 import { IocContainer } from '@tsoa/runtime'
 import { container } from 'tsyringe'
+import { Logger } from 'pino'
+
+import env, { type Env, EnvToken } from './env.js'
+import { logger, LoggerToken } from './lib/logger.js'
 
 export const iocContainer: IocContainer = {
   get: <T>(controller: { prototype: T }): T => {
     return container.resolve<T>(controller as never)
   },
 }
+
+export function resetContainer() {
+  container.reset()
+  container.register<Env>(EnvToken, { useValue: env })
+  container.register<Logger>(LoggerToken, { useValue: logger })
+}

src/lib/chainNode.ts

@@ -1,15 +1,19 @@
-import { Logger } from 'pino'
+import { type Logger } from 'pino'
 import { ApiPromise, WsProvider, Keyring, SubmittableResult } from '@polkadot/api'
 import { blake2AsHex } from '@polkadot/util-crypto'
 import { SubmittableExtrinsic } from '@polkadot/api/types'
 import type { u128 } from '@polkadot/types'
+import { inject, singleton } from 'tsyringe'
+import { Mutex } from 'async-mutex'
 
 import { serviceState } from './service-watcher/statusPoll.js'
 import { TransactionState } from '../models/transaction.js'
 import type { Payload, Output, Metadata } from './payload.js'
 import { HEX } from '../models/strings.js'
 import { hexToBs58 } from '../utils/hex.js'
 import { trim0x } from './utils/shared.js'
+import { LoggerToken } from './logger.js'
+import { type Env, EnvToken } from '../env.js'
 
 const processRanTopic = blake2AsHex('utxoNFT.ProcessRan')
 
@@ -48,18 +52,20 @@ type EventData =
     }
   | undefined
 
+@singleton()
 export default class ChainNode {
   private provider: WsProvider
   private api: ApiPromise
   private keyring: Keyring
   private logger: Logger
   private userUri: string
   private lastSubmittedNonce: number
+  private mutex = new Mutex()
 
-  constructor({ host, port, logger, userUri }: NodeCtorConfig) {
+  constructor(@inject(LoggerToken) logger: Logger, @inject(EnvToken) env: Env) {
     this.logger = logger.child({ module: 'ChainNode' })
-    this.provider = new WsProvider(`ws://${host}:${port}`)
-    this.userUri = userUri
+    this.provider = new WsProvider(`ws://${env.NODE_HOST}:${env.NODE_PORT}`)
+    this.userUri = env.USER_URI
     this.api = new ApiPromise({ provider: this.provider })
     this.keyring = new Keyring({ type: 'sr25519' })
     this.lastSubmittedNonce = -1
@@ -69,11 +75,11 @@ export default class ChainNode {
     })
 
     this.api.on('disconnected', () => {
-      this.logger.warn(`Disconnected from substrate node at ${host}:${port}`)
+      this.logger.warn(`Disconnected from substrate node at ${env.NODE_HOST}:${env.NODE_PORT}`)
     })
 
     this.api.on('connected', () => {
-      this.logger.info(`Connected to substrate node at ${host}:${port}`)
+      this.logger.info(`Connected to substrate node at ${env.NODE_HOST}:${env.NODE_PORT}`)
     })
 
     this.api.on('error', (err) => {
@@ -135,9 +141,14 @@ export default class ChainNode {
     await this.api.isReady
     const extrinsic = this.api.tx.utxoNFT.runProcess(process, inputs, outputsAsMaps)
     const account = this.keyring.addFromUri(this.userUri)
-    const nextTxPoolNonce = (await this.api.rpc.system.accountNextIndex(account.publicKey)).toNumber()
-    const nonce = Math.max(nextTxPoolNonce, this.lastSubmittedNonce + 1)
-    this.lastSubmittedNonce = nonce
+
+    const nonce = await this.mutex.runExclusive(async () => {
+      const nextTxPoolNonce = (await this.api.rpc.system.accountNextIndex(account.publicKey)).toNumber()
+      const nonce = Math.max(nextTxPoolNonce, this.lastSubmittedNonce + 1)
+      this.lastSubmittedNonce = nonce
+      return nonce
+    })
+
     const signed = await extrinsic.signAsync(account, { nonce })
     return signed
   }

src/lib/db/index.ts

@@ -287,7 +287,7 @@ export default class Database {
       .returning(transactionColumns)
   }
 
-  getTransaction = async (id: UUID) => {
+  getTransaction = async (id: UUID): Promise<[Transaction] | []> => {
     return this.db().transaction().select(transactionColumns).where({ id })
   }
 

src/lib/logger.ts

@@ -1,6 +1,7 @@
 import { pino, Logger } from 'pino'
 
 import env from '../env.js'
+import { container } from 'tsyringe'
 
 export const logger: Logger = pino(
   {
@@ -10,3 +11,6 @@ export const logger: Logger = pino(
   },
   process.stdout
 )
+
+export const LoggerToken = Symbol('Logger')
+container.register<Logger>(LoggerToken, { useValue: logger })