fix: print response log only when response arrives (#1392)

src/handlers/GraphQLHandler.ts

@@ -197,8 +197,7 @@ Consider naming this operation or using "graphql.operation" request handler to i
 
   log(
     request: Request,
-    response: SerializedResponse,
-    handler: this,
+    response: SerializedResponse<any>,
     parsedRequest: ParsedGraphQLRequest,
   ) {
     const loggedRequest = prepareRequest(request)

src/handlers/RequestHandler.ts

@@ -140,7 +140,6 @@ export abstract class RequestHandler<
   abstract log(
     request: Request,
     response: SerializedResponse<any>,
-    handler: this,
     parsedResult: ParsedResult,
   ): void
 

src/handlers/RestHandler.ts

@@ -1,5 +1,5 @@
 import { body, cookie, json, text, xml } from '../context'
-import { SerializedResponse } from '../setupWorker/glossary'
+import type { SerializedResponse } from '../setupWorker/glossary'
 import { ResponseResolutionContext } from '../utils/getResponse'
 import { devUtils } from '../utils/internal/devUtils'
 import { isStringEqual } from '../utils/internal/isStringEqual'
@@ -174,7 +174,7 @@ export class RestHandler<
     return matchesMethod && parsedResult.matches
   }
 
-  log(request: RequestType, response: SerializedResponse) {
+  log(request: RequestType, response: SerializedResponse<any>) {
     const publicUrl = getPublicUrlFromRequest(request)
     const loggedRequest = prepareRequest(request)
     const loggedResponse = prepareResponse(response)
@@ -190,10 +190,7 @@ export class RestHandler<
       'color:inherit',
     )
     console.log('Request', loggedRequest)
-    console.log('Handler:', {
-      mask: this.info.path,
-      resolver: this.resolver,
-    })
+    console.log('Handler:', this)
     console.log('Response', loggedResponse)
     console.groupEnd()
   }

src/setupWorker/start/createFallbackRequestListener.ts

@@ -5,7 +5,6 @@ import {
 } from '@mswjs/interceptors'
 import { FetchInterceptor } from '@mswjs/interceptors/lib/interceptors/fetch'
 import { XMLHttpRequestInterceptor } from '@mswjs/interceptors/lib/interceptors/XMLHttpRequest'
-import type { RequestHandler } from '../../handlers/RequestHandler'
 import {
   SerializedResponse,
   SetupWorkerInternalContext,
@@ -14,6 +13,8 @@ import {
 import type { RequiredDeep } from '../../typeUtils'
 import { handleRequest } from '../../utils/handleRequest'
 import { MockedRequest } from '../../utils/request/MockedRequest'
+import { serializeResponse } from '../../utils/logging/serializeResponse'
+import { createResponseFromIsomorphicResponse } from '../../utils/request/createResponseFromIsomorphicResponse'
 
 export function createFallbackRequestListener(
   context: SetupWorkerInternalContext,
@@ -45,17 +46,15 @@ export function createFallbackRequestListener(
             delay: response.delay,
           }
         },
-        onMockedResponseSent(
-          response,
-          { handler, publicRequest, parsedRequest },
-        ) {
+        onMockedResponse(_, { handler, publicRequest, parsedRequest }) {
           if (!options.quiet) {
-            handler.log(
-              publicRequest,
-              response,
-              handler as RequestHandler,
-              parsedRequest,
-            )
+            context.emitter.once('response:mocked', (response) => {
+              handler.log(
+                publicRequest,
+                serializeResponse(response),
+                parsedRequest,
+              )
+            })
           }
         },
       },
@@ -66,6 +65,20 @@ export function createFallbackRequestListener(
     }
   })
 
+  interceptor.on('response', (request, response) => {
+    if (!request.id) {
+      return
+    }
+
+    const browserResponse = createResponseFromIsomorphicResponse(response)
+
+    if (response.headers.get('x-powered-by') === 'msw') {
+      context.emitter.emit('response:mocked', browserResponse, request.id)
+    } else {
+      context.emitter.emit('response:bypass', browserResponse, request.id)
+    }
+  })
+
   interceptor.apply()
 
   return interceptor

src/setupWorker/start/createRequestListener.ts

@@ -11,10 +11,10 @@ import {
 import { NetworkError } from '../../utils/NetworkError'
 import { parseWorkerRequest } from '../../utils/request/parseWorkerRequest'
 import { handleRequest } from '../../utils/handleRequest'
-import { RequestHandler } from '../../handlers/RequestHandler'
 import { RequiredDeep } from '../../typeUtils'
 import { MockedResponse } from '../../response'
 import { devUtils } from '../../utils/internal/devUtils'
+import { serializeResponse } from '../../utils/logging/serializeResponse'
 
 export const createRequestListener = (
   context: SetupWorkerInternalContext,
@@ -41,7 +41,10 @@ export const createRequestListener = (
           onPassthroughResponse() {
             messageChannel.postMessage('NOT_FOUND')
           },
-          async onMockedResponse(response) {
+          async onMockedResponse(
+            response,
+            { handler, publicRequest, parsedRequest },
+          ) {
             if (response.body instanceof ReadableStream) {
               throw new Error(
                 devUtils.formatMessage(
@@ -54,7 +57,7 @@ export const createRequestListener = (
             const responseBodyBuffer = await responseInstance.arrayBuffer()
 
             // If the mocked response has no body, keep it that way.
-            // Sending an empty ArrayBuffer to the worker will cause
+            // Sending an empty "ArrayBuffer" to the worker will cause
             // the worker constructing "new Response(new ArrayBuffer(0))"
             // which will throw on responses that must have no body (i.e. 204).
             const responseBody =
@@ -68,21 +71,16 @@ export const createRequestListener = (
               },
               [responseBodyBuffer],
             )
-          },
-          onMockedResponseSent(
-            response,
-            { handler, publicRequest, parsedRequest },
-          ) {
-            if (options.quiet) {
-              return
-            }
 
-            handler.log(
-              publicRequest,
-              response,
-              handler as RequestHandler,
-              parsedRequest,
-            )
+            if (!options.quiet) {
+              context.emitter.once('response:mocked', (response) => {
+                handler.log(
+                  publicRequest,
+                  serializeResponse(response),
+                  parsedRequest,
+                )
+              })
+            }
           },
         },
       )

src/utils/handleRequest.test.ts

@@ -26,7 +26,6 @@ const options: RequiredDeep<SharedOptions> = {
 const callbacks: Partial<Record<keyof HandleRequestOptions<any>, any>> = {
   onPassthroughResponse: jest.fn(),
   onMockedResponse: jest.fn(),
-  onMockedResponseSent: jest.fn(),
 }
 
 beforeEach(() => {
@@ -67,7 +66,6 @@ test('returns undefined for a request with the "x-msw-bypass" header equal to "t
   expect(options.onUnhandledRequest).not.toHaveBeenCalled()
   expect(callbacks.onPassthroughResponse).toHaveBeenNthCalledWith(1, request)
   expect(callbacks.onMockedResponse).not.toHaveBeenCalled()
-  expect(callbacks.onMockedResponseSent).not.toHaveBeenCalled()
 })
 
 test('does not bypass a request with "x-msw-bypass" header set to arbitrary value', async () => {
@@ -93,7 +91,6 @@ test('does not bypass a request with "x-msw-bypass" header set to arbitrary valu
   expect(result).not.toBeUndefined()
   expect(options.onUnhandledRequest).not.toHaveBeenCalled()
   expect(callbacks.onMockedResponse).toHaveBeenCalledTimes(1)
-  expect(callbacks.onMockedResponseSent).toHaveBeenCalledTimes(1)
 })
 
 test('reports request as unhandled when it has no matching request handlers', async () => {
@@ -120,7 +117,6 @@ test('reports request as unhandled when it has no matching request handlers', as
   })
   expect(callbacks.onPassthroughResponse).toHaveBeenNthCalledWith(1, request)
   expect(callbacks.onMockedResponse).not.toHaveBeenCalled()
-  expect(callbacks.onMockedResponseSent).not.toHaveBeenCalled()
 })
 
 test('returns undefined and warns on a request handler that returns no response', async () => {
@@ -148,7 +144,6 @@ test('returns undefined and warns on a request handler that returns no response'
   expect(options.onUnhandledRequest).not.toHaveBeenCalled()
   expect(callbacks.onPassthroughResponse).toHaveBeenNthCalledWith(1, request)
   expect(callbacks.onMockedResponse).not.toHaveBeenCalled()
-  expect(callbacks.onMockedResponseSent).not.toHaveBeenCalled()
 
   expect(console.warn).toHaveBeenCalledTimes(1)
   const warning = (console.warn as unknown as jest.SpyInstance).mock.calls[0][0]
@@ -195,11 +190,6 @@ test('returns the mocked response for a request with a matching request handler'
     mockedResponse,
     lookupResult,
   )
-  expect(callbacks.onMockedResponseSent).toHaveBeenNthCalledWith(
-    1,
-    mockedResponse,
-    lookupResult,
-  )
 })
 
 test('returns a transformed response if the "transformResponse" option is provided', async () => {
@@ -239,11 +229,6 @@ test('returns a transformed response if the "transformResponse" option is provid
     finalResponse,
     lookupResult,
   )
-  expect(callbacks.onMockedResponseSent).toHaveBeenNthCalledWith(
-    1,
-    finalResponse,
-    lookupResult,
-  )
 })
 
 it('returns undefined without warning on a passthrough request', async () => {
@@ -270,5 +255,4 @@ it('returns undefined without warning on a passthrough request', async () => {
   expect(options.onUnhandledRequest).not.toHaveBeenCalled()
   expect(callbacks.onPassthroughResponse).toHaveBeenNthCalledWith(1, request)
   expect(callbacks.onMockedResponse).not.toHaveBeenCalled()
-  expect(callbacks.onMockedResponseSent).not.toHaveBeenCalled()
 })

src/utils/handleRequest.ts

@@ -37,15 +37,6 @@ export interface HandleRequestOptions<ResponseType> {
     response: ResponseType,
     handler: RequiredDeep<ResponseLookupResult>,
   ): void
-
-  /**
-   * Invoked when the mocked response is sent.
-   * Respects the response delay duration.
-   */
-  onMockedResponseSent?(
-    response: ResponseType,
-    handler: RequiredDeep<ResponseLookupResult>,
-  ): void
 }
 
 export async function handleRequest<
@@ -138,10 +129,6 @@ Expected response resolver to return a mocked response Object, but got %s. The o
     requiredLookupResult,
   )
 
-  handleRequestOptions?.onMockedResponseSent?.(
-    transformedResponse,
-    requiredLookupResult,
-  )
   emitter.emit('request:end', request)
 
   return transformedResponse

src/utils/logging/prepareRequest.ts

@@ -1,9 +1,19 @@
-import { MockedRequest } from '../request/MockedRequest.js'
+import type { DefaultBodyType } from '../../handlers/RequestHandler.js'
+import type { MockedRequest } from '../request/MockedRequest.js'
+
+export interface LoggedRequest {
+  id: string
+  url: URL
+  method: string
+  headers: Record<string, string>
+  cookies: Record<string, string>
+  body: DefaultBodyType
+}
 
 /**
  * Formats a mocked request for introspection in browser's console.
  */
-export function prepareRequest(request: MockedRequest) {
+export function prepareRequest(request: MockedRequest): LoggedRequest {
   return {
     ...request,
     body: request.body,

src/utils/logging/serializeResponse.ts

@@ -0,0 +1,11 @@
+import { flattenHeadersObject, headersToObject } from 'headers-polyfill'
+import type { SerializedResponse } from '../../setupWorker/glossary'
+
+export function serializeResponse(source: Response): SerializedResponse<any> {
+  return {
+    status: source.status,
+    statusText: source.statusText,
+    headers: flattenHeadersObject(headersToObject(source.headers)),
+    body: source.body,
+  }
+}

src/utils/request/createResponseFromIsomorphicResponse.ts

@@ -0,0 +1,34 @@
+import { encodeBuffer, IsomorphicResponse } from '@mswjs/interceptors'
+
+const noop = () => {
+  throw new Error('Not implemented')
+}
+
+export function createResponseFromIsomorphicResponse(
+  response: IsomorphicResponse,
+): Response {
+  return {
+    ...response,
+    ok: response.status >= 200 && response.status < 300,
+    url: '',
+    type: 'default',
+    status: response.status,
+    statusText: response.statusText,
+    headers: response.headers,
+    body: new ReadableStream(),
+    redirected: response.headers.get('Location') != null,
+    async text() {
+      return response.body || ''
+    },
+    async json() {
+      return JSON.parse(response.body || '')
+    },
+    async arrayBuffer() {
+      return encodeBuffer(response.body || '')
+    },
+    bodyUsed: false,
+    formData: noop,
+    blob: noop,
+    clone: noop,
+  }
+}

test/msw-api/setup-worker/fallback-mode/fallback-mode.test.ts

@@ -3,6 +3,7 @@ import { SetupWorkerApi } from 'msw'
 import { createTeardown } from 'fs-teardown'
 import { Page, pageWith, Response, ScenarioApi } from 'page-with'
 import { fromTemp } from '../../../support/utils'
+import { waitFor } from '../../../support/waitFor'
 
 let runtime: ScenarioApi
 
@@ -83,13 +84,15 @@ test('responds with a mocked response to a handled request', async () => {
   const response = await request('https://api.github.com/users/octocat')
 
   // Prints the request message group in the console.
-  expect(runtime.consoleSpy.get('startGroupCollapsed')).toEqual(
-    expect.arrayContaining([
-      expect.stringMatching(
-        /\[MSW\] \d{2}:\d{2}:\d{2} GET https:\/\/api\.github\.com\/users\/octocat 200 OK/,
-      ),
-    ]),
-  )
+  await waitFor(() => {
+    expect(runtime.consoleSpy.get('startGroupCollapsed')).toEqual(
+      expect.arrayContaining([
+        expect.stringMatching(
+          /\[MSW\] \d{2}:\d{2}:\d{2} GET https:\/\/api\.github\.com\/users\/octocat 200 OK/,
+        ),
+      ]),
+    )
+  })
 
   // Responds with a mocked response.
   expect(response.status).toEqual(200)