Reintroduce HTTP request logging for OAuth

.changeset/neat-pans-nail.md

@@ -0,0 +1,5 @@
+---
+"@shopify/shopify-api": patch
+---
+
+Reintroduced logging of HTML requests for OAuth processes, which was incorrectly removed when the new clients were introduced.

packages/shopify-api/lib/auth/oauth/oauth.ts

@@ -12,7 +12,6 @@ import {
   abstractConvertIncomingResponse,
   abstractConvertResponse,
   abstractConvertHeaders,
-  abstractFetch,
   AdapterResponse,
   AdapterHeaders,
   Cookies,
@@ -21,6 +20,7 @@ import {
 } from '../../../runtime/http';
 import {logger, ShopifyLogger} from '../../logger';
 import {DataType} from '../../clients/types';
+import {fetchRequestFactory} from '../../utils/fetch-request';
 
 import {
   SESSION_COOKIE_NAME,
@@ -190,7 +190,7 @@ export function callback(config: ConfigInterface): OAuthCallback {
 
     const cleanShop = sanitizeShop(config)(query.get('shop')!, true)!;
 
-    const postResponse = await abstractFetch(
+    const postResponse = await fetchRequestFactory(config)(
       `https://${cleanShop}/admin/oauth/access_token`,
       {
         method: 'POST',

packages/shopify-api/lib/auth/oauth/token-exchange.ts

@@ -3,8 +3,8 @@ import {decodeSessionToken} from '../../session/decode-session-token';
 import {sanitizeShop} from '../../utils/shop-validator';
 import {ConfigInterface} from '../../base-types';
 import {Session} from '../../session/session';
-import {abstractFetch} from '../../../runtime';
 import {DataType} from '../../clients/types';
+import {fetchRequestFactory} from '../../utils/fetch-request';
 
 import {createSession} from './create-session';
 import {AccessTokenResponse} from './types';
@@ -47,7 +47,7 @@ export function tokenExchange(config: ConfigInterface): TokenExchange {
 
     const cleanShop = sanitizeShop(config)(shop, true)!;
 
-    const postResponse = await abstractFetch(
+    const postResponse = await fetchRequestFactory(config)(
       `https://${cleanShop}/admin/oauth/access_token`,
       {
         method: 'POST',

packages/shopify-api/lib/utils/__tests__/fetch-request.test.ts

@@ -0,0 +1,147 @@
+import {testConfig} from '../../__tests__/test-config';
+import {queueMockResponse} from '../../__tests__/test-helper';
+import {LogSeverity} from '../../types';
+import {fetchRequestFactory} from '../fetch-request';
+
+describe('fetchRequest', () => {
+  const domain = 'test.example.io';
+  const url = `https://${domain}`;
+  const successResponse = {field1: 1, field2: 'value'};
+
+  it('skips logging if logger.httpRequests is false', async () => {
+    // GIVEN
+    const logFn = jest.fn();
+    const config = testConfig({
+      logger: {log: logFn, level: LogSeverity.Debug, httpRequests: false},
+    });
+
+    queueMockResponse(JSON.stringify(successResponse));
+
+    // WHEN
+    const response = await fetchRequestFactory(config)(url);
+    const responseBody = await response.json();
+
+    // THEN
+    expect(logFn).not.toHaveBeenCalled();
+    expect(responseBody).toEqual(successResponse);
+    expect({method: 'GET', domain, path: '/'}).toMatchMadeHttpRequest();
+  });
+
+  it('skips logging if logger.level is higher than Debug', async () => {
+    // GIVEN
+    const logFn = jest.fn();
+    const config = testConfig({
+      logger: {log: logFn, level: LogSeverity.Info, httpRequests: true},
+    });
+
+    queueMockResponse(JSON.stringify(successResponse));
+
+    // WHEN
+    const response = await fetchRequestFactory(config)(url);
+    const responseBody = await response.json();
+
+    // THEN
+    expect(logFn).not.toHaveBeenCalled();
+    expect(responseBody).toEqual(successResponse);
+    expect({method: 'GET', domain, path: '/'}).toMatchMadeHttpRequest();
+  });
+
+  it('logs GET requests when configured', async () => {
+    // GIVEN
+    const logFn = jest.fn();
+    const config = testConfig({
+      logger: {log: logFn, level: LogSeverity.Debug, httpRequests: true},
+    });
+
+    queueMockResponse(JSON.stringify(successResponse));
+
+    // WHEN
+    const response = await fetchRequestFactory(config)(url);
+    const responseBody = await response.json();
+
+    // THEN
+    expect(logFn).toHaveBeenNthCalledWith(
+      1,
+      LogSeverity.Debug,
+      `[shopify-api/DEBUG] Making HTTP request | {method: GET, url: ${url}}`,
+    );
+    expect(logFn).toHaveBeenNthCalledWith(
+      2,
+      LogSeverity.Debug,
+      `[shopify-api/DEBUG] HTTP request completed | {method: GET, url: ${url}, status: 200}`,
+    );
+    expect(responseBody).toEqual(successResponse);
+    expect({method: 'GET', domain, path: '/'}).toMatchMadeHttpRequest();
+  });
+
+  it('logs POST requests with the body when configured', async () => {
+    // GIVEN
+    const logFn = jest.fn();
+    const config = testConfig({
+      logger: {log: logFn, level: LogSeverity.Debug, httpRequests: true},
+    });
+
+    queueMockResponse(JSON.stringify(successResponse));
+
+    // WHEN
+    const requestBody = {
+      requestField1: 1,
+    };
+    const response = await fetchRequestFactory(config)(url, {
+      method: 'POST',
+      body: JSON.stringify(requestBody),
+    });
+    const responseBody = await response.json();
+
+    // THEN
+    expect(logFn).toHaveBeenNthCalledWith(
+      1,
+      LogSeverity.Debug,
+      `[shopify-api/DEBUG] Making HTTP request | {method: POST, url: ${url}, body: ${JSON.stringify(requestBody)}}`,
+    );
+    expect(logFn).toHaveBeenNthCalledWith(
+      2,
+      LogSeverity.Debug,
+      `[shopify-api/DEBUG] HTTP request completed | {method: POST, url: ${url}, status: 200}`,
+    );
+    expect(responseBody).toEqual(successResponse);
+    expect({
+      method: 'POST',
+      domain,
+      path: '/',
+      data: requestBody,
+    }).toMatchMadeHttpRequest();
+  });
+
+  it('logs non-200 response codes', async () => {
+    // GIVEN
+    const logFn = jest.fn();
+    const config = testConfig({
+      logger: {log: logFn, level: LogSeverity.Debug, httpRequests: true},
+    });
+
+    queueMockResponse(JSON.stringify(successResponse), {statusCode: 400});
+
+    // WHEN
+    const response = await fetchRequestFactory(config)(url);
+    const responseBody = await response.json();
+
+    // THEN
+    expect(logFn).toHaveBeenNthCalledWith(
+      1,
+      LogSeverity.Debug,
+      `[shopify-api/DEBUG] Making HTTP request | {method: GET, url: ${url}}`,
+    );
+    expect(logFn).toHaveBeenNthCalledWith(
+      2,
+      LogSeverity.Debug,
+      `[shopify-api/DEBUG] HTTP request completed | {method: GET, url: ${url}, status: 400}`,
+    );
+    expect(responseBody).toEqual(successResponse);
+    expect({
+      method: 'GET',
+      domain,
+      path: '/',
+    }).toMatchMadeHttpRequest();
+  });
+});

packages/shopify-api/lib/utils/fetch-request.ts

@@ -0,0 +1,35 @@
+import {logger} from '../logger';
+import {LogSeverity} from '../types';
+import {abstractFetch} from '../../runtime';
+import {ConfigInterface} from '../base-types';
+
+export function fetchRequestFactory(config: ConfigInterface) {
+  return async function fetchRequest(
+    url: string,
+    options?: RequestInit,
+  ): Promise<Response> {
+    const log = logger(config);
+    const doLog =
+      config.logger.httpRequests && config.logger.level === LogSeverity.Debug;
+
+    if (doLog) {
+      log.debug('Making HTTP request', {
+        method: options?.method || 'GET',
+        url,
+        ...(options?.body && {body: options?.body}),
+      });
+    }
+
+    const response = await abstractFetch(url, options);
+
+    if (doLog) {
+      log.debug('HTTP request completed', {
+        method: options?.method || 'GET',
+        url,
+        status: response.status,
+      });
+    }
+
+    return response;
+  };
+}