Display request log once the response is signaled by the worker #1343

kettanaito · 2022-07-18T12:43:47Z

Scope

Improves an existing behavior

Compatibility

This is a breaking change

Feature description

Current behavior

Right now MSW prints the [MSW] /resource 200 OK request log immediately once the mocked response has been sent to the worker.

Proposed behavior

Instead, print the request log once the worker reports the response event. This way if the response has some delay, or took some time to process for other reasons, the developer would know that, translating the moment when the request log has appeared to the moment when the response has been truly handled by the worker.

Links

msw/src/setupWorker/start/createRequestListener.ts

Lines 66 to 80 in 6c6e119

    
           onMockedResponseSent( 
        
             response, 
        
             { handler, publicRequest, parsedRequest }, 
        
           ) { 
        
             if (options.quiet) { 
        
               return 
        
             } 
        
             handler.log( 
        
               publicRequest, 
        
               response, 
        
               handler as RequestHandler, 
        
               parsedRequest, 
        
             ) 
        
           },

This is the wrong place to call handler.log(). We should migrate from this and reconsider if onMockedResponseSent is used for any other purpose.

We may also consider rewriting onMockedResponseSent to actually await the response event from the worker and then dispatching its callback. For example, handleRequest() accepts context.emitter as an input, so it can create a listener on the response events:

// handleRequest.ts
// We have two distinct events for different response resolution type,
// so listen to both. One request will always have only one of the response
// events emitter by the worker. 
context.emitter.once('response:mocked', handleResponse)
context.emitter.once('response:bypassed', handleResponse)

const handleResponse = (response, requestId) => {
  // Ignore response events from irrelevant requests.
  if (request.id !== requestId) {
    return
  }

  onMockedResponseSent?.(info)
}

The text was updated successfully, but these errors were encountered:

kettanaito · 2022-09-10T00:34:36Z

Released: v0.47.1 🎉

This has been released in v0.47.1!

📄 Release notes
📦 npm package

Make sure to always update to the latest version (npm i msw@latest) to get the newest features and bug fixes.

Predictable release automation by @ossjs/release.

kleinfreund · 2022-09-14T10:30:37Z

I’ve noticed an increase in the amount of logged “[MSW]” messages due to this change (implemented in #1392). Entries like “[MSW] 12:23:53 GET http://localhost:8000/path (200 OK)” now appear multiple times despite the related request only being made once. I also started getting the following warning (see also #785):

events.js:46 MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 response:mocked listeners added. Use emitter.setMaxListeners() to increase limit

Is this supposed to work this way?

kettanaito · 2022-09-15T09:28:03Z

@kleinfreund, thanks for reporting this! No, that sounds like an issue. I think I've noticed this happening yesterday as well. Please, do you have a repo example to reproduce this?

events.js:46 MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 response:mocked listeners added. Use emitter.setMaxListeners() to increase limit

This happens in Node, right? The introduced change didn't affect Node.

kleinfreund · 2022-09-15T09:44:44Z

@kettanaito Hey.

Please, do you have a repo example to reproduce this?

I don’t have a minimal reproduction, but a branch that I’m working on where this occurs. Though just now I’m having trouble reproducing this again.

On https://github.com/kleinfreund/kuma-gui/tree/feat/rework-dataplanes-view, I have currently pinned msw to 1.47.0. Yesterday, unpinning the version and updating to 1.47.2 and starting the application (yarn install, yarn run dev) made the issue visible, but that doesn't occur anymore. I have no idea why.

This happens in Node, right? The introduced change didn't affect Node.

Yes, I think? I’m working on a Vue app using Vite as the general tooling wrapper. To use Vite, I did make sure that my application code never imports a file that imports msw/node. The mock server is set-up using setupWorker. Tests are a different matter. There, msw/node is in use.

Let me keep msw 1.47.2 installed and continue development and see if it re-appears with further use.

Previous content, unrelated to this issue:

I’m running into an unrelated issue with the headers-polyfill.

Error

✘ [ERROR] [plugin vite:dep-pre-bundle] Missing "./lib" export in "headers-polyfill" package

    node_modules/msw/lib/index.js:455:25:
      455 │ var import_lib = require("headers-polyfill/lib");
          ╵                          ~~~~~~~~~~~~~~~~~~~~~~

  This error came from the "onResolve" callback registered here:

    node_modules/esbuild/lib/main.js:855:22:
      855 │         let promise = setup({
          ╵                       ^

    at setup (file:///home/phil/kong/kuma-gui/node_modules/vite/dist/node/chunks/dep-a713b95d.js:35072:19)
    at handlePlugins (/home/phil/kong/kuma-gui/node_modules/esbuild/lib/main.js:855:23)
    at Object.buildOrServe (/home/phil/kong/kuma-gui/node_modules/esbuild/lib/main.js:1149:7)
    at /home/phil/kong/kuma-gui/node_modules/esbuild/lib/main.js:2117:17
    at new Promise (<anonymous>)
    at Object.build (/home/phil/kong/kuma-gui/node_modules/esbuild/lib/main.js:2116:14)
    at build (/home/phil/kong/kuma-gui/node_modules/esbuild/lib/main.js:1963:51)
    at runOptimizeDeps (file:///home/phil/kong/kuma-gui/node_modules/vite/dist/node/chunks/dep-a713b95d.js:42345:26)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)

✘ [ERROR] [plugin vite:dep-pre-bundle] Missing "./lib" export in "headers-polyfill" package

    node_modules/@mswjs/interceptors/lib/IsomorphicRequest.js:40:20:
      40 │ var lib_1 = require("headers-polyfill/lib");
         ╵                     ~~~~~~~~~~~~~~~~~~~~~~

  This error came from the "onResolve" callback registered here:

    node_modules/esbuild/lib/main.js:855:22:
      855 │         let promise = setup({
          ╵                       ^

    at setup (file:///home/phil/kong/kuma-gui/node_modules/vite/dist/node/chunks/dep-a713b95d.js:35072:19)
    at handlePlugins (/home/phil/kong/kuma-gui/node_modules/esbuild/lib/main.js:855:23)
    at Object.buildOrServe (/home/phil/kong/kuma-gui/node_modules/esbuild/lib/main.js:1149:7)
    at /home/phil/kong/kuma-gui/node_modules/esbuild/lib/main.js:2117:17
    at new Promise (<anonymous>)
    at Object.build (/home/phil/kong/kuma-gui/node_modules/esbuild/lib/main.js:2116:14)
    at build (/home/phil/kong/kuma-gui/node_modules/esbuild/lib/main.js:1963:51)
    at runOptimizeDeps (file:///home/phil/kong/kuma-gui/node_modules/vite/dist/node/chunks/dep-a713b95d.js:42345:26)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)

Fixed in: mswjs/interceptors#286

kleinfreund · 2022-09-15T09:50:12Z

@kettanaito Regarding the headers-polyfill error, I think that project’s package.json file is missing the module specifier definitions when using headers-polyfill/lib:

package.json diff

{
  "name": "headers-polyfill",
  "version": "3.1.0",
  "description": "A native \"Headers\" class polyfill.",
  "main": "./lib/index.js",
  "module": "./lib/esm/index.js",
  "types": "./lib/index.d.ts",
  "exports": {
    ".": {
      "types": "./lib/index.d.ts",
      "require": "./lib/index.js",
      "default": "./lib/esm/index.js"
    },
+   "./lib": {
+     "types": "./lib/index.d.ts",
+     "require": "./lib/index.js",
+     "default": "./lib/esm/index.js"
+   }
  },
  "repository": "https://github.com/mswjs/headers-polyfill",
  "author": "Artem Zakharchenko",
  "license": "MIT",
  "scripts": {
    "start": "tsup --watch",
    "clean": "rimraf lib",
    "build": "yarn clean && tsup",
    "test": "jest",
    "release": "release publish",
    "prepublishOnly": "yarn test && yarn build"
  },
  "files": [
    "lib",
    "README.md"
  ],
  "devDependencies": {
    "@ossjs/release": "^0.3.0",
    "@types/jest": "^28.1.4",
    "jest": "^28.1.2",
    "jest-environment-jsdom": "^28.1.2",
    "rimraf": "^3.0.2",
    "ts-jest": "^28.0.5",
    "tsup": "^6.2.3",
    "typescript": "4.3.2"
  }
}

kettanaito · 2022-09-15T10:17:05Z

@kleinfreund, you're right! But I'd fix it the other way around: we should use direct imports now instead of /lib directory. I believe once we update headers-polyfill in the dev environment it starts failing too.

kleinfreund · 2022-09-15T10:28:46Z

@kettanaito Yep, expanding the exports like I did was just a means of verifying what’s actually missing. Using the bare headers-polyfill module specifier seems better because adding /lib would just be redundant now.

kleinfreund · 2022-09-15T11:20:46Z

I’ve managed to reproduce the issue again (I did update msw to the latest version and manually patched one msw instance of importing headers-polyfill/lib to get the latest dependencies to work) so here is a more complete trace:

events.js:46 MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 response:mocked listeners added. Use emitter.setMaxListeners() to increase limit
    at _addListener (http://localhost:8080/node_modules/.vite/deps/msw.js?v=711daf8b:597:19)
    at StrictEventEmitter2.addListener (http://localhost:8080/node_modules/.vite/deps/msw.js?v=711daf8b:608:14)
    at StrictEventEmitter2.once (http://localhost:8080/node_modules/.vite/deps/msw.js?v=711daf8b:868:36)
    at Object.onMockedResponse (http://localhost:8080/node_modules/.vite/deps/msw.js?v=711daf8b:22101:34)
ProcessEmitWarning		@	events.js:46
_addListener			@	events.js:219
addListener			@	events.js:227
StrictEventEmitter2.once	@	StrictEventEmitter.js:34
onMockedResponse		@	createRequestListener.ts:76
await in onMockedResponse (async)		
handleRequest			@	handleRequest.ts:127
await in handleRequest (async)		
(anonymous)			@	createRequestListener.ts:34
(anonymous)			@	setupWorker.ts:93

I think it took a bit of navigating around in the app to start seeing the increase in MSW output and eventually the warning. I feel like more listeners of something are registered than are being cleaned up.

kettanaito · 2022-09-15T11:39:52Z

@kleinfreund I've fixed this in headers-polyfill@3.1. Updated @mswjs/interceptors as well. MSW update open in #1407.

SerkanSipahi · 2022-09-17T11:26:06Z

I can confim @kleinfreund !

I still get "MaxListenersExceededWarning" (Chrome Browser) although as you (@kettanaito) recommended (#1407) to fully re-install (delete msw -> add mws@0.47.3, also tried rm -rf node_modules).

Some side Note: I switched from 0.43.0 to 0.47.3 and now new additional strange behavior appeared. The logs in the devTools are displayed (logged) multiple/many/>=10x times in the browser. In 0.43.0 everything works fine.

DevTools Log

MaxListenersExceededWarning
multiple logs

kleinfreund · 2022-09-17T11:39:14Z

@SerkanSipahi I'm pretty sure that both symptoms are caused by the same issue.

@kettanaito Do you want a new issue being reported for this? I'm happy to do so.

SerkanSipahi · 2022-09-17T11:41:00Z

@kleinfreund

I see, you are right!

I’ve noticed an increase in the amount of logged “[MSW]” messages due to this change (implemented in #1392). Entries like “[MSW] 12:23:53 GET http://localhost:8000/path (200 OK)” now appear multiple times despite the related request only being made once. I also started getting the following warning (see also #785):

kettanaito · 2022-09-19T12:06:44Z

@kleinfreund, yes please! It'd help other people discover it. Thank you.

kleinfreund · 2022-09-20T07:16:42Z

@kettanaito Not a problem. I’ve filed an issue for this here: #1411

kettanaito added the feature label Jul 18, 2022

kettanaito self-assigned this Sep 1, 2022

kettanaito mentioned this issue Sep 7, 2022

fix: print response log only when response arrives #1392

Merged

kettanaito closed this as completed in #1392 Sep 7, 2022

kleinfreund mentioned this issue Sep 20, 2022

Duplicate log output and MaxListenersExceededWarning warning (regression in 0.47.1) #1411

Closed

4 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Display request log once the response is signaled by the worker #1343

Display request log once the response is signaled by the worker #1343

kettanaito commented Jul 18, 2022

kettanaito commented Sep 10, 2022

kleinfreund commented Sep 14, 2022 •

edited

kettanaito commented Sep 15, 2022 •

edited

kleinfreund commented Sep 15, 2022 •

edited

kleinfreund commented Sep 15, 2022 •

edited

kettanaito commented Sep 15, 2022

kleinfreund commented Sep 15, 2022

kleinfreund commented Sep 15, 2022 •

edited

kettanaito commented Sep 15, 2022

SerkanSipahi commented Sep 17, 2022 •

edited

kleinfreund commented Sep 17, 2022

SerkanSipahi commented Sep 17, 2022

kettanaito commented Sep 19, 2022

kleinfreund commented Sep 20, 2022

Display request log once the response is signaled by the worker #1343

Display request log once the response is signaled by the worker #1343

Comments

kettanaito commented Jul 18, 2022

Scope

Compatibility

Feature description

Current behavior

Proposed behavior

Links

kettanaito commented Sep 10, 2022

Released: v0.47.1 🎉

kleinfreund commented Sep 14, 2022 • edited

kettanaito commented Sep 15, 2022 • edited

kleinfreund commented Sep 15, 2022 • edited

kleinfreund commented Sep 15, 2022 • edited

kettanaito commented Sep 15, 2022

kleinfreund commented Sep 15, 2022

kleinfreund commented Sep 15, 2022 • edited

kettanaito commented Sep 15, 2022

SerkanSipahi commented Sep 17, 2022 • edited

DevTools Log

kleinfreund commented Sep 17, 2022

SerkanSipahi commented Sep 17, 2022

kettanaito commented Sep 19, 2022

kleinfreund commented Sep 20, 2022

kleinfreund commented Sep 14, 2022 •

edited

kettanaito commented Sep 15, 2022 •

edited

kleinfreund commented Sep 15, 2022 •

edited

kleinfreund commented Sep 15, 2022 •

edited

kleinfreund commented Sep 15, 2022 •

edited

SerkanSipahi commented Sep 17, 2022 •

edited