diff --git a/.changeset/brave-pots-rest.md b/.changeset/brave-pots-rest.md new file mode 100644 index 00000000..821c6120 --- /dev/null +++ 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 index 7a8b321e..edb64ee9 100644 --- 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 index 7ad240dc..b91a2a94 100644 --- 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 index ccbcc7c9..e07c1959 100644 --- 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 index c2d02cd9..cc9aec97 100644 --- 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 index 02978b19..b7b5c950 100644 --- 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 index 88ea2ff7..a045988e 100644 --- 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 -): 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 = {}): Promise => { - 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 => { - 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 index 375b432b..5bc9725f 100644 --- 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 => { 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 => { 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 => { @@ -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() }) }) diff --git a/packages/open-payments/src/client/requests.ts b/packages/open-payments/src/client/requests.ts index f8811184..67f7529e 100644 --- a/packages/open-payments/src/client/requests.ts +++ b/packages/open-payments/src/client/requests.ts @@ -3,9 +3,10 @@ import { ResponseValidator, isValidationError } from '@interledger/openapi' import { BaseDeps } from '.' import { createHeaders } from '@interledger/http-signature-utils' import { OpenPaymentsClientError } from './error' +import { Logger } from 'pino' // @ts-expect-error We know we are importing an ESM module into our CJS file, so ignore warnings for types -import type { KyInstance } from 'ky' +import type { KyInstance, NormalizedOptions } from 'ky' interface GetArgs { url: string @@ -224,61 +225,111 @@ const checkUrlProtocol = (deps: BaseDeps, url: string): string => { return requestUrl.href } -type CreateHttpClientArgs = { +interface CreateHttpClientArgs { + logger: Logger requestTimeoutMs: number -} & ( - | { privateKey?: KeyObject; keyId?: string } + requestSigningArgs?: AuthenticatedHttpClientArgs +} + +type AuthenticatedHttpClientArgs = + | { privateKey: KeyObject; keyId: string } | { authenticatedRequestInterceptor: InterceptorFn } -) export type HttpClient = KyInstance -export type InterceptorFn = (request: Request) => Request | Promise +export type InterceptorFn = ( + request: Request +) => Request | Promise | void | Promise export const createHttpClient = async ( args: CreateHttpClientArgs ): Promise => { const { default: ky } = await import('ky') + const { requestTimeoutMs, requestSigningArgs, logger } = args + const kyInstance = ky.create({ - timeout: args.requestTimeoutMs, + timeout: requestTimeoutMs, headers: { Accept: 'application/json', 'Content-Type': 'application/json' } }) - let requestInterceptor: InterceptorFn | undefined + const beforeRequestHooks = [] + const afterResponseHooks = [] - if ('authenticatedRequestInterceptor' in args) { - requestInterceptor = (request) => { - if (requestShouldBeAuthorized(request)) { - return args.authenticatedRequestInterceptor(request) - } + const requestLogger: InterceptorFn = async (request) => { + const requestBody = request.body ? await request.clone().json() : undefined + + logger.debug( + { + method: request.method, + url: request.url, + body: requestBody + }, + 'Sending request' + ) + } - return request + const responseLogger = async ( + request: Request, + _: NormalizedOptions, + response: Response + ) => { + let responseBody + try { + responseBody = await response.clone().text() + responseBody = JSON.parse(responseBody) + } catch { + // Ignore if we can't parse the response body (or no body exists) } - } else { - requestInterceptor = (request) => { - const { privateKey, keyId } = args - if (requestShouldBeAuthorized(request)) { - return signRequest(request, { privateKey, keyId }) + logger.debug( + { + method: request.method, + url: response.url, + body: responseBody, + status: response.status + }, + 'Received response' + ) + } + + beforeRequestHooks.push(requestLogger) + afterResponseHooks.push(responseLogger) + + if (requestSigningArgs) { + let requestInterceptor: InterceptorFn | undefined + if ('authenticatedRequestInterceptor' in requestSigningArgs) { + requestInterceptor = (request) => { + if (requestShouldBeAuthorized(request)) { + return requestSigningArgs.authenticatedRequestInterceptor(request) + } + + return request } + } else { + requestInterceptor = (request) => { + const { privateKey, keyId } = requestSigningArgs - return request - } - } + if (requestShouldBeAuthorized(request)) { + return signRequest(request, { privateKey, keyId }) + } - if (requestInterceptor) { - return kyInstance.extend({ - hooks: { - beforeRequest: [requestInterceptor] + return request } - }) + } + + beforeRequestHooks.push(requestInterceptor) } - return kyInstance + return kyInstance.extend({ + hooks: { + beforeRequest: beforeRequestHooks, + afterResponse: afterResponseHooks + } + }) } export const requestShouldBeAuthorized = (request: Request) => diff --git a/packages/open-payments/src/test/helpers.ts b/packages/open-payments/src/test/helpers.ts index fae8e328..c27cdf5c 100644 --- a/packages/open-payments/src/test/helpers.ts +++ b/packages/open-payments/src/test/helpers.ts @@ -35,9 +35,12 @@ export const getDefaultHttpClient = async (): ReturnType< typeof createHttpClient > => createHttpClient({ + logger: silentLogger, requestTimeoutMs: 1000, - keyId, - privateKey: generateKeyPairSync('ed25519').privateKey + requestSigningArgs: { + keyId, + privateKey: generateKeyPairSync('ed25519').privateKey + } }) export const mockOpenApiResponseValidators = () => ({