chore(open-payments): adding debug logs for client initialization & r…

…equests (#485) * chore(open-payments): parse error objects, and return error codes * chore(open-payments): add missing assertions, update tests * chore(open-payments): update README * chore(open-payments): add changeset * feat(open-payments): adding logging request and response hooks for http client * feat(open-payments): adding logging during client initialization * chore(open-payments): make default logging silent * chore(open-payments): add changeset * chore(open-payments): simplify assertion * chore(open-payments): remove old changeset * chore(open-payments): remove optional chaining * chore(ci): update pnpm action
interledger · Jul 4, 2024 · d7535db · d7535db
1 parent 27d915e
commit d7535db
Show file tree

Hide file tree

Showing 10 changed files with 227 additions and 95 deletions.
diff --git a/.changeset/brave-pots-rest.md b/.changeset/brave-pots-rest.md
@@ -0,0 +1,7 @@
+---
+'@interledger/open-payments': minor
+---
+
+- Adding debug logs during client initialization
+- Adding debug logs for requests and responses in the http client
+- Making log level `silent` by default
diff --git a/.github/workflows/deploy-docs.yaml b/.github/workflows/deploy-docs.yaml
@@ -26,10 +26,9 @@ jobs:
         with:
           node-version: 20
 
-      - uses: pnpm/action-setup@v2
+      - uses: pnpm/action-setup@v4
         name: Install pnpm
         with:
-          version: 8
           run_install: false
 
       - name: Install dependencies

diff --git a/.github/workflows/env-setup/action.yaml b/.github/workflows/env-setup/action.yaml
@@ -4,9 +4,7 @@ description: "Sets node version, init pnpm, restore cache"
 runs:
   using: "composite"
   steps:
-    - uses: pnpm/action-setup@v2
-      with:
-        version: 8
+    - uses: pnpm/action-setup@v4
     - uses: actions/setup-node@v3
       with:
         node-version: 20

diff --git a/.github/workflows/test-docs-build.yml b/.github/workflows/test-docs-build.yml
@@ -20,10 +20,9 @@ jobs:
         with:
           node-version: 20
 
-      - uses: pnpm/action-setup@v2
+      - uses: pnpm/action-setup@v4
         name: Install pnpm
         with:
-          version: 8
           run_install: false
 
       - name: Install dependencies

diff --git a/packages/open-payments/README.md b/packages/open-payments/README.md
@@ -56,7 +56,7 @@ const incomingPayment = await client.walletAddress.get({
 | ------------------- | --------------------------------------------------------------------------------------------------------------- |
 | `requestTimeoutMs`  | (optional) The timeout in ms for each request by the client. Defaults to 5000.                                  |
 | `logger`            | (optional) The custom logger to provide for the client. Defaults to pino logger.                                |
-| `logLevel`          | (optional) The log level for the client. Defaults to `info`.                                                    |
+| `logLevel`          | (optional) The log level for the client. Defaults to `silent`.                                                  |
 | `validateResponses` | (optional) Enables or disables response validation against the Open Payments OpenAPI specs. Defaults to `true`. |
 
 ### `AuthenticatedClient`

diff --git a/packages/open-payments/src/client/index.test.ts b/packages/open-payments/src/client/index.test.ts
@@ -86,7 +86,7 @@ describe('Client', (): void => {
       } catch (error) {
         assert.ok(error instanceof OpenPaymentsClientError)
         expect(error.message).toBe(
-          'Could not load private key when creating Open Payments client'
+          'Could not load private key when creating authenticated client'
         )
         expect(error.description).toBe('Key is not a valid file')
       }
@@ -104,7 +104,7 @@ describe('Client', (): void => {
       } catch (error) {
         assert.ok(error instanceof OpenPaymentsClientError)
         expect(error.message).toBe(
-          'Could not load private key when creating Open Payments client'
+          'Could not load private key when creating authenticated client'
         )
         expect(error.description).toBe('Key is not a valid path or file')
       }

diff --git a/packages/open-payments/src/client/index.ts b/packages/open-payments/src/client/index.ts
@@ -97,31 +97,31 @@ export interface CollectionRequestArgs
   walletAddress: string
 }
 
-const parseKey = (
-  args: Partial<CreateAuthenticatedClientArgs>
-): KeyObject | undefined => {
-  if (!args.privateKey) {
-    return undefined
+const parseKey = (deps: { logger: Logger }, privateKey: KeyLike): KeyObject => {
+  if (privateKey instanceof KeyObject) {
+    deps.logger.debug('Loading key from KeyObject')
+    return privateKey
   }
 
-  if (args.privateKey instanceof KeyObject) {
-    return args.privateKey
-  }
-
-  if (args.privateKey instanceof Buffer) {
+  if (privateKey instanceof Buffer) {
     try {
-      return createPrivateKey(args.privateKey)
+      deps.logger.debug('Loading key from Buffer')
+      return createPrivateKey(privateKey)
     } catch {
       throw new Error('Key is not a valid file')
     }
   }
 
-  if (fs.existsSync(path.resolve(process.cwd(), args.privateKey))) {
-    return loadKey(path.resolve(process.cwd(), args.privateKey))
+  const keyFilePath = path.resolve(process.cwd(), privateKey)
+
+  if (fs.existsSync(keyFilePath)) {
+    deps.logger.debug(`Loading key from file path: ${keyFilePath}`)
+    return loadKey(keyFilePath)
   }
 
   try {
-    return createPrivateKey(args.privateKey)
+    deps.logger.debug('Loading key from string')
+    return createPrivateKey(privateKey)
   } catch {
     throw new Error('Key is not a valid path or file')
   }
@@ -132,14 +132,16 @@ const createUnauthenticatedDeps = async ({
   validateResponses = true,
   ...args
 }: Partial<CreateUnauthenticatedClientArgs> = {}): Promise<UnauthenticatedClientDeps> => {
-  const logger = args?.logger ?? createLogger({ name: 'Open Payments Client' })
+  const logger =
+    args.logger ??
+    createLogger({ name: 'Open Payments Client', level: 'silent' })
   if (args.logLevel) {
     logger.level = args.logLevel
   }
 
   const httpClient = await createHttpClient({
-    requestTimeoutMs:
-      args?.requestTimeoutMs ?? config.DEFAULT_REQUEST_TIMEOUT_MS
+    logger,
+    requestTimeoutMs: args.requestTimeoutMs ?? config.DEFAULT_REQUEST_TIMEOUT_MS
   })
 
   let walletAddressServerOpenApi: OpenAPI | undefined
@@ -166,40 +168,49 @@ const createAuthenticatedClientDeps = async ({
 }:
   | CreateAuthenticatedClientArgs
   | CreateAuthenticatedClientWithReqInterceptorArgs): Promise<AuthenticatedClientDeps> => {
-  const logger = args?.logger ?? createLogger({ name: 'Open Payments Client' })
+  const logger =
+    args.logger ??
+    createLogger({ name: 'Open Payments Client', level: 'silent' })
   if (args.logLevel) {
     logger.level = args.logLevel
   }
 
-  let privateKey: KeyObject | undefined
-  try {
-    privateKey = parseKey(args)
-  } catch (error) {
-    const errorMessage =
-      'Could not load private key when creating Open Payments client'
-    const description = error instanceof Error ? error.message : 'Unknown error'
-
-    logger.error({ description }, errorMessage)
-
-    throw new OpenPaymentsClientError(errorMessage, {
-      description
-    })
-  }
-
   let httpClient: HttpClient
 
   if ('authenticatedRequestInterceptor' in args) {
     httpClient = await createHttpClient({
+      logger,
       requestTimeoutMs:
-        args?.requestTimeoutMs ?? config.DEFAULT_REQUEST_TIMEOUT_MS,
-      authenticatedRequestInterceptor: args.authenticatedRequestInterceptor
+        args.requestTimeoutMs ?? config.DEFAULT_REQUEST_TIMEOUT_MS,
+      requestSigningArgs: {
+        authenticatedRequestInterceptor: args.authenticatedRequestInterceptor
+      }
     })
   } else {
+    let privateKey: KeyObject
+    try {
+      privateKey = parseKey({ logger }, args.privateKey)
+    } catch (error) {
+      const errorMessage =
+        'Could not load private key when creating authenticated client'
+      const description =
+        error instanceof Error ? error.message : 'Unknown error'
+
+      logger.error({ description }, errorMessage)
+
+      throw new OpenPaymentsClientError(errorMessage, {
+        description
+      })
+    }
+
     httpClient = await createHttpClient({
+      logger,
       requestTimeoutMs:
-        args?.requestTimeoutMs ?? config.DEFAULT_REQUEST_TIMEOUT_MS,
-      privateKey,
-      keyId: args.keyId
+        args.requestTimeoutMs ?? config.DEFAULT_REQUEST_TIMEOUT_MS,
+      requestSigningArgs: {
+        privateKey,
+        keyId: args.keyId
+      }
     })
   }
 
@@ -250,6 +261,16 @@ export const createUnauthenticatedClient = async (
   const { resourceServerOpenApi, walletAddressServerOpenApi, ...baseDeps } =
     await createUnauthenticatedDeps(args)
 
+  baseDeps.logger.debug(
+    {
+      validateResponses: !!args.validateResponses,
+      useHttp: baseDeps.useHttp,
+      requestTimeoutMs:
+        args.requestTimeoutMs ?? config.DEFAULT_REQUEST_TIMEOUT_MS
+    },
+    'Created unauthenticated client'
+  )
+
   return {
     walletAddress: createWalletAddressRoutes({
       ...baseDeps,
@@ -335,6 +356,18 @@ export async function createAuthenticatedClient(
     ...baseDeps
   } = await createAuthenticatedClientDeps(args)
 
+  baseDeps.logger.debug(
+    {
+      walletAddressUrl: args.walletAddressUrl,
+      ...('keyId' in args ? { keyId: args.keyId } : {}),
+      validateResponses: !!args.validateResponses,
+      useHttp: baseDeps.useHttp,
+      requestTimeoutMs:
+        args.requestTimeoutMs ?? config.DEFAULT_REQUEST_TIMEOUT_MS
+    },
+    'Created authenticated client'
+  )
+
   return {
     incomingPayment: createIncomingPaymentRoutes({
       ...baseDeps,

diff --git a/packages/open-payments/src/client/requests.test.ts b/packages/open-payments/src/client/requests.test.ts
@@ -10,7 +10,11 @@ import {
 } from './requests'
 import { generateKeyPairSync } from 'crypto'
 import nock from 'nock'
-import { createTestDeps, mockOpenApiResponseValidators } from '../test/helpers'
+import {
+  createTestDeps,
+  mockOpenApiResponseValidators,
+  silentLogger
+} from '../test/helpers'
 import { OpenPaymentsClientError } from './error'
 import assert from 'assert'
 import ky, { HTTPError } from 'ky'
@@ -39,9 +43,12 @@ describe('requests', (): void => {
 
   beforeAll(async () => {
     httpClient = await createHttpClient({
+      logger: silentLogger,
       requestTimeoutMs: 1000000,
-      privateKey,
-      keyId
+      requestSigningArgs: {
+        privateKey,
+        keyId
+      }
     })
     deps = await createTestDeps({
       httpClient
@@ -52,7 +59,14 @@ describe('requests', (): void => {
     test('sets timeout properly', async (): Promise<void> => {
       const kyCreateSpy = jest.spyOn(ky, 'create')
 
-      await createHttpClient({ requestTimeoutMs: 1000, privateKey, keyId })
+      await createHttpClient({
+        logger: silentLogger,
+        requestTimeoutMs: 1000,
+        requestSigningArgs: {
+          privateKey,
+          keyId
+        }
+      })
 
       expect(kyCreateSpy).toHaveBeenCalledWith(
         expect.objectContaining({ timeout: 1000 })
@@ -61,7 +75,14 @@ describe('requests', (): void => {
     test('sets headers properly', async (): Promise<void> => {
       const kyCreateSpy = jest.spyOn(ky, 'create')
 
-      await createHttpClient({ requestTimeoutMs: 1000, privateKey, keyId })
+      await createHttpClient({
+        logger: silentLogger,
+        requestTimeoutMs: 1000,
+        requestSigningArgs: {
+          privateKey,
+          keyId
+        }
+      })
 
       expect(kyCreateSpy).toHaveBeenCalledWith(
         expect.objectContaining({
@@ -81,15 +102,24 @@ describe('requests', (): void => {
       const kyExtendSpy = jest.spyOn(kyInstance, 'extend')
 
       await createHttpClient({
+        logger: silentLogger,
         requestTimeoutMs: 0,
-        authenticatedRequestInterceptor: (config) => config
-      })
-
-      expect(kyExtendSpy).toHaveBeenCalledWith({
-        hooks: {
-          beforeRequest: [expect.any(Function)]
+        requestSigningArgs: {
+          privateKey,
+          keyId
         }
       })
+
+      assert.ok(kyExtendSpy.mock.calls[0][0].hooks?.beforeRequest)
+      expect(kyExtendSpy.mock.calls[0][0].hooks?.beforeRequest).toHaveLength(2)
+
+      const requestSignerWithPrivateKey =
+        kyExtendSpy.mock.calls[0][0].hooks.beforeRequest[1]
+
+      const request = new Request('http://localhost:1000')
+
+      // eslint-disable-next-line @typescript-eslint/no-non-null-assertion
+      expect(requestSignerWithPrivateKey(request, undefined!)).toBeDefined()
     })
 
     test('sets authenticated request interceptor', async (): Promise<void> => {
@@ -99,16 +129,28 @@ describe('requests', (): void => {
 
       const kyExtendSpy = jest.spyOn(kyInstance, 'extend')
 
+      const mockedAuthenticatedRequestInterceptor = jest.fn()
+
       await createHttpClient({
+        logger: silentLogger,
         requestTimeoutMs: 0,
-        authenticatedRequestInterceptor: (config) => config
-      })
-
-      expect(kyExtendSpy).toHaveBeenCalledWith({
-        hooks: {
-          beforeRequest: [expect.any(Function)]
+        requestSigningArgs: {
+          authenticatedRequestInterceptor: mockedAuthenticatedRequestInterceptor
         }
       })
+
+      assert.ok(kyExtendSpy.mock.calls[0][0].hooks?.beforeRequest)
+      expect(kyExtendSpy.mock.calls[0][0].hooks?.beforeRequest).toHaveLength(2)
+
+      const authenticatedRequestInterceptor =
+        kyExtendSpy.mock.calls[0][0].hooks.beforeRequest[1]
+
+      const request = new Request('http://localhost:1000', { method: 'POST' })
+
+      // eslint-disable-next-line @typescript-eslint/no-non-null-assertion
+      authenticatedRequestInterceptor(request, undefined!)
+
+      expect(mockedAuthenticatedRequestInterceptor).toHaveBeenCalled()
     })
   })