Repository: nock/nock
Pull request #2592 (2024-02-25 02:28:09)

fix: replace debug with node debug
I did not fix the unit test as I could not fix it properly. But lets discuss this.

Uzlopak: Just one remark, which I realized later:

debuglog does not exist on browsers. So if we have the necessity to support browsers, it wont work. But I think the support of browsers got lost few major versions ago?
mikicho: @Uzlopak I don't think we support Browser (I think because we use `setImmdeiate` for example). But if (when?) we complete [this effort](https://github.com/nock/nock/pull/2517), we may want to support browsers as well. 
Uzlopak: Well, i dont know why for browsers nock should be used, but i wanted to say, why maybe debug was used in the first place. 
mikicho: @Uzlopak why not? MSW is very popular in the browser.
Uzlopak: @mikicho @gr2m 
PTAL
mikicho: @Uzlopak What is the problem with the tests?
Uzlopak: added test.
Uzlopak: Rerunning the tests and it run through
gr2m: @mikicho if changes look good to you, let's merge
mikicho: LGTM 

Patch:
diff --git a/README.md b/README.md
index 43f1eaa..da15ee9 100644
--- a/README.md
+++ b/README.md
@@ -1643,10 +1643,10 @@ It does this by manipulating the modules cache of Node in a way that conflicts w
 
 ## Debugging
 
-Nock uses [`debug`](https://github.com/visionmedia/debug), so just run with environmental variable `DEBUG` set to `nock.*`.
+Nock uses node internals [`debuglog`](https://nodejs.org/api/util.html#utildebuglogsection-callbackg), so just run with environmental variable `NODE_DEBUG` set to `nock:*`.
 
 ```console
-user@local$ DEBUG=nock.* node my_test.js
+user@local$ NODE_DEBUG=nock:* node my_test.js
 ```
 
 Each step in the matching process is logged this way and can be useful when determining why a request was not intercepted by Nock.
@@ -1660,11 +1660,11 @@ await got('http://example.com/?foo=bar&baz=foz')
 ```
 
 ```console
-user@local$ DEBUG=nock.scope:example.com node my_test.js
+user@local$ DEBUG=nock:scope:example.com node my_test.js
 ...
-nock.scope:example.com Interceptor queries: {"foo":"bar"} +1ms
-nock.scope:example.com     Request queries: {"foo":"bar","baz":"foz"} +0ms
-nock.scope:example.com query matching failed +0ms
+NOCK:SCOPE:EXAMPLE.COM 103514: Interceptor queries: {"foo":"bar"}
+NOCK:SCOPE:EXAMPLE.COM 103514:     Request queries: {"foo":"bar","baz":"foz"}
+NOCK:SCOPE:EXAMPLE.COM 103514: query matching failed
 ```
 
 ## Contributing
diff --git a/lib/back.js b/lib/back.js
index 4128c0d..bd0d4fd 100644
--- a/lib/back.js
+++ b/lib/back.js
@@ -9,10 +9,9 @@ const {
   removeAll: cleanAll,
 } = require('./intercept')
 const { loadDefs, define } = require('./scope')
-
+const { back: debug } = require('./debug')
 const { format } = require('util')
 const path = require('path')
-const debug = require('debug')('nock.back')
 
 let _mode = null
 
diff --git a/lib/common.js b/lib/common.js
index a1f20fa..ea6e976 100644
--- a/lib/common.js
+++ b/lib/common.js
@@ -1,6 +1,6 @@
 'use strict'
 
-const debug = require('debug')('nock.common')
+const { common: debug } = require('./debug')
 const timers = require('timers')
 const url = require('url')
 const util = require('util')
diff --git a/lib/debug.js b/lib/debug.js
new file mode 100644
index 0000000..080a6f8
--- /dev/null
+++ b/lib/debug.js
@@ -0,0 +1,12 @@
+'use strict'
+
+const { debuglog } = require('util')
+
+module.exports.back = debuglog('nock:back')
+module.exports.common = debuglog('nock:common')
+module.exports.intercept = debuglog('nock:intercept')
+module.exports.request_overrider = debuglog('nock:request_overrider')
+module.exports.playback_interceptor = debuglog('nock:playback_interceptor')
+module.exports.recorder = debuglog('nock:recorder')
+module.exports.socket = debuglog('nock:socket')
+module.exports.scopeDebuglog = namespace => debuglog(`nock:scope:${namespace}`)
diff --git a/lib/intercept.js b/lib/intercept.js
index 9811f07..d5038a7 100644
--- a/lib/intercept.js
+++ b/lib/intercept.js
@@ -8,7 +8,7 @@ const { InterceptedRequestRouter } = require('./intercepted_request_router')
 const common = require('./common')
 const { inherits } = require('util')
 const http = require('http')
-const debug = require('debug')('nock.intercept')
+const { intercept: debug } = require('./debug')
 const globalEmitter = require('./global_emitter')
 const { createResponse } = require('./create_response')
 
diff --git a/lib/intercepted_request_router.js b/lib/intercepted_request_router.js
index d82c244..a0a118d 100644
--- a/lib/intercepted_request_router.js
+++ b/lib/intercepted_request_router.js
@@ -1,6 +1,6 @@
 'use strict'
 
-const debug = require('debug')('nock.request_overrider')
+const { request_overrider: debug } = require('./debug')
 const {
   IncomingMessage,
   ClientRequest,
diff --git a/lib/interceptor.js b/lib/interceptor.js
index 67ef8b9..da09703 100644
--- a/lib/interceptor.js
+++ b/lib/interceptor.js
@@ -242,14 +242,7 @@ module.exports = class Interceptor {
   }
 
   match(req, options, body) {
-    // check if the logger is enabled because the stringifies can be expensive.
-    if (this.scope.logger.enabled) {
-      this.scope.logger(
-        'attempting match %s, body = %s',
-        stringify(options),
-        stringify(body),
-      )
-    }
+    this.scope.logger('attempting match %j, body = %j', options, body)
 
     const method = (options.method || 'GET').toUpperCase()
     let { path = '/' } = options
diff --git a/lib/playback_interceptor.js b/lib/playback_interceptor.js
index a0bae8e..0d3bd6f 100644
--- a/lib/playback_interceptor.js
+++ b/lib/playback_interceptor.js
@@ -3,7 +3,7 @@
 const stream = require('stream')
 const util = require('util')
 const zlib = require('zlib')
-const debug = require('debug')('nock.playback_interceptor')
+const { playback_interceptor: debug } = require('./debug')
 const common = require('./common')
 
 function parseJSONRequestBody(req, requestBody) {
diff --git a/lib/recorder.js b/lib/recorder.js
index 91b3e3f..d402d6b 100644
--- a/lib/recorder.js
+++ b/lib/recorder.js
@@ -1,6 +1,6 @@
 'use strict'
 
-const debug = require('debug')('nock.recorder')
+const { recorder: debug } = require('./debug')
 const querystring = require('querystring')
 const { inspect } = require('util')
 
diff --git a/lib/scope.js b/lib/scope.js
index eb51e80..2d29a56 100644
--- a/lib/scope.js
+++ b/lib/scope.js
@@ -3,11 +3,11 @@
 /**
  * @module nock/scope
  */
+const { scopeDebuglog } = require('./debug')
 const { addInterceptor, isOn } = require('./intercept')
 const common = require('./common')
 const assert = require('assert')
 const url = require('url')
-const debug = require('debug')('nock.scope')
 const { EventEmitter } = require('events')
 const Interceptor = require('./interceptor')
 
@@ -99,7 +99,7 @@ class Scope extends EventEmitter {
       logNamespace = this.urlParts.host
     }
 
-    this.logger = debug.extend(logNamespace)
+    this.logger = scopeDebuglog(logNamespace)
   }
 
   add(key, interceptor) {
diff --git a/lib/socket.js b/lib/socket.js
index 4651aa7..69fc6cc 100644
--- a/lib/socket.js
+++ b/lib/socket.js
@@ -1,7 +1,7 @@
 'use strict'
 
 const { EventEmitter } = require('events')
-const debug = require('debug')('nock.socket')
+const { socket: debug } = require('./debug')
 
 module.exports = class Socket extends EventEmitter {
   constructor(options) {
diff --git a/package-lock.json b/package-lock.json
index e5d901e..f56b7c4 100644
--- a/package-lock.json
+++ b/package-lock.json
@@ -9,7 +9,6 @@
       "version": "0.0.0-development",
       "license": "MIT",
       "dependencies": {
-        "debug": "^4.1.0",
         "json-stringify-safe": "^5.0.1",
         "propagate": "^2.0.0"
       },
@@ -4214,6 +4213,7 @@
       "version": "4.3.4",
       "resolved": "https://registry.npmjs.org/debug/-/debug-4.3.4.tgz",
       "integrity": "sha512-PRWFHuSU3eDtQJPvnNY7Jcket1j0t5OuOsFzPPzsekD52Zl8qUfFIPEiswXqIvHWGVHOgX+7G/vCNNhehwxfkQ==",
+      "dev": true,
       "dependencies": {
         "ms": "2.1.2"
       },
@@ -8778,7 +8778,8 @@
     "node_modules/ms": {
       "version": "2.1.2",
       "resolved": "https://registry.npmjs.org/ms/-/ms-2.1.2.tgz",
-      "integrity": "sha512-sGkPx+VjMtmA6MX27oA4FBFELFCZZ4S4XqeGOXCv68tT+jb3vk/RyaKWP0PTKyWtmLSM0b+adUTEvbs1PEaH2w=="
+      "integrity": "sha512-sGkPx+VjMtmA6MX27oA4FBFELFCZZ4S4XqeGOXCv68tT+jb3vk/RyaKWP0PTKyWtmLSM0b+adUTEvbs1PEaH2w==",
+      "dev": true
     },
     "node_modules/nanoid": {
       "version": "3.3.1",
@@ -19248,6 +19249,7 @@
       "version": "4.3.4",
       "resolved": "https://registry.npmjs.org/debug/-/debug-4.3.4.tgz",
       "integrity": "sha512-PRWFHuSU3eDtQJPvnNY7Jcket1j0t5OuOsFzPPzsekD52Zl8qUfFIPEiswXqIvHWGVHOgX+7G/vCNNhehwxfkQ==",
+      "dev": true,
       "requires": {
         "ms": "2.1.2"
       }
@@ -22630,7 +22632,8 @@
     "ms": {
       "version": "2.1.2",
       "resolved": "https://registry.npmjs.org/ms/-/ms-2.1.2.tgz",
-      "integrity": "sha512-sGkPx+VjMtmA6MX27oA4FBFELFCZZ4S4XqeGOXCv68tT+jb3vk/RyaKWP0PTKyWtmLSM0b+adUTEvbs1PEaH2w=="
+      "integrity": "sha512-sGkPx+VjMtmA6MX27oA4FBFELFCZZ4S4XqeGOXCv68tT+jb3vk/RyaKWP0PTKyWtmLSM0b+adUTEvbs1PEaH2w==",
+      "dev": true
     },
     "nanoid": {
       "version": "3.3.1",
diff --git a/package.json b/package.json
index a5fadd5..fd9a2db 100644
--- a/package.json
+++ b/package.json
@@ -22,7 +22,6 @@
   "main": "./index.js",
   "types": "types",
   "dependencies": {
-    "debug": "^4.1.0",
     "json-stringify-safe": "^5.0.1",
     "propagate": "^2.0.0"
   },


Test patch:
diff --git a/tests/got/fixtures/logging.mjs b/tests/got/fixtures/logging.mjs
new file mode 100644
index 0000000..154db5d
--- /dev/null
+++ b/tests/got/fixtures/logging.mjs
@@ -0,0 +1,7 @@
+import nock from '../../../index.js'
+import got from 'got'
+
+nock('http://example.test').post('/deep/link').reply(200, 'Hello World!')
+
+const exampleBody = 'Hello yourself!'
+await got.post('http://example.test/deep/link', { body: exampleBody })
diff --git a/tests/got/test_logging.js b/tests/got/test_logging.js
index 39dfb09..3a3dac6 100644
--- a/tests/got/test_logging.js
+++ b/tests/got/test_logging.js
@@ -1,55 +1,96 @@
 'use strict'
 
-const debug = require('debug')
-const sinon = require('sinon')
+const { join } = require('node:path')
+const { spawn } = require('node:child_process')
 const { expect } = require('chai')
-const nock = require('../..')
-const got = require('./got_client')
 
 describe('Logging using the `debug` package', () => {
-  let logFn
-  beforeEach(() => {
-    logFn = sinon.stub(debug, 'log')
-    debug.enable('nock*')
-  })
-
-  afterEach(() => {
-    debug.disable('nock*')
-  })
-
   it('match debugging works', async () => {
-    nock('http://example.test').post('/deep/link').reply(200, 'Hello World!')
-
-    const exampleBody = 'Hello yourself!'
-    await got.post('http://example.test/deep/link', { body: exampleBody })
-
     // the log function will have been a few dozen times, there are a few specific to matching we want to validate:
 
-    // the log when an interceptor is chosen
-    expect(logFn).to.have.been.calledWith(
-      sinon.match('matched base path (1 interceptor)'),
-    )
+    let resolveTest
+    let rejectTest
+    const p = new Promise((resolve, reject) => {
+      resolveTest = resolve
+      rejectTest = reject
+    })
+    const assertions = [
+      /NOCK:BACK \d+: New nock back mode: dryrun/,
+      /NOCK:RECORDER \d+: 0 restoring all the overridden http\/https properties/,
+      /NOCK:COMMON \d+: restoring requests/,
+      /NOCK:INTERCEPT \d+: restoring overridden ClientRequest/,
+      /NOCK:INTERCEPT \d+: - ClientRequest was not overridden/,
+      /NOCK:COMMON \d+: overriding requests/,
+      /NOCK:COMMON \d+: - overriding request for http/,
+      /NOCK:COMMON \d+: - overridden request for http/,
+      /NOCK:COMMON \d+: - overriding request for https/,
+      /NOCK:COMMON \d+: - overridden request for https/,
+      /NOCK:INTERCEPT \d+: Overriding ClientRequest/,
+      /NOCK:INTERCEPT \d+: ClientRequest overridden/,
+      /NOCK:SCOPE:EXAMPLE.TEST \d+: reply.headers: {}/,
+      /NOCK:SCOPE:EXAMPLE.TEST \d+: reply.rawHeaders: \[\]/,
+      /NOCK:COMMON \d+: options.hostname in the end: "example.test"/,
+      /NOCK:COMMON \d+: options.host in the end: "example.test:80"/,
+      /NOCK:INTERCEPT \d+: interceptors for "example.test:80"/,
+      /NOCK:INTERCEPT \d+: filtering interceptors for basepath http:\/\/example.test:80/,
+      /NOCK:INTERCEPT \d+: matched base path \(1 interceptor\)/,
+      /NOCK:COMMON \d+: options.host: example.test:80/,
+      /NOCK:COMMON \d+: options.hostname in the end: "example.test"/,
+      /NOCK:COMMON \d+: options.host in the end: "example.test:80"/,
+      /NOCK:INTERCEPT \d+: interceptors for "example.test:80"/,
+      /NOCK:INTERCEPT \d+: filtering interceptors for basepath http:\/\/example.test:80/,
+      /NOCK:INTERCEPT \d+: matched base path \(1 interceptor\)/,
+      /NOCK:INTERCEPT \d+: using 1 interceptors/,
+      /NOCK:REQUEST_OVERRIDER \d+: request write/,
+      /NOCK:REQUEST_OVERRIDER \d+: request end/,
+      /NOCK:REQUEST_OVERRIDER \d+: ending/,
+      /NOCK:SCOPE:EXAMPLE.TEST \d+: attempting match {"protocol":"http:","hostname":"example.test","hash":"","search":"","pathname":"\/deep\/link","path":"\/deep\/link","href":"http:\/\/example.test\/deep\/link","method":"POST","retry":{"limit":2,"methods":\["GET","PUT","HEAD","DELETE","OPTIONS","TRACE"\],"statusCodes":\[408,413,429,500,502,503,504,521,522,524\],"errorCodes":\["ETIMEDOUT","ECONNRESET","EADDRINUSE","ECONNREFUSED","EPIPE","ENOTFOUND","ENETUNREACH","EAI_AGAIN"\],"maxRetryAfter":null},"headers":{"user-agent":"got \(https:\/\/github.com\/sindresorhus\/got\)","content-length":"15","accept-encoding":"gzip, deflate, br"},"hooks":{"init":\[\],"beforeRequest":\[\],"beforeRedirect":\[\],"beforeRetry":\[\],"beforeError":\[\],"afterResponse":\[\]},"decompress":true,"throwHttpErrors":true,"followRedirect":true,"isStream":false,"responseType":"text","resolveBodyOnly":false,"maxRedirects":10,"prefixUrl":"","methodRewriting":true,"ignoreInvalidCookies":false,"http2":false,"allowGetBody":false,"pagination":{"countLimit":null,"backoff":0,"requestLimit":10000,"stackAllItems":true},"cacheOptions":{},"url":"http:\/\/example.test\/deep\/link","username":"","password":"","proto":"http","port":80,"host":"example.test:80"}, body = "Hello yourself!"/,
+      /NOCK:SCOPE:EXAMPLE.TEST \d+: query matching skipped/,
+      /NOCK:SCOPE:EXAMPLE.TEST \d+: matching http:\/\/example.test:80\/deep\/link to POST http:\/\/example.test:80\/deep\/link: true/,
+      /NOCK:SCOPE:EXAMPLE.TEST \d+: interceptor identified, starting mocking/,
+      /NOCK:SCOPE:EXAMPLE.TEST \d+: response.rawHeaders: \[\]/,
+      /NOCK:SCOPE:EXAMPLE.TEST \d+: emitting response/,
+      /^$/,
+    ]
 
-    // the log of the Interceptor match
-    expect(logFn).to.have.been.calledWith(
-      // debug namespace for the scope that includes the host
-      sinon.match('nock.scope:example.test'),
-      // This is a JSON blob which contains, among other things the complete
-      // request URL.
-      sinon.match('"href":"http://example.test/deep/link"'),
-      // This is the JSON-stringified body.
-      `"${exampleBody}"`,
-    )
-
-    expect(logFn).to.have.been.calledWith(sinon.match('query matching skipped'))
-
-    expect(logFn).to.have.been.calledWith(
-      sinon.match(
-        'matching http://example.test:80/deep/link to POST http://example.test:80/deep/link: true',
-      ),
-    )
-    expect(logFn).to.have.been.calledWith(
-      sinon.match('interceptor identified, starting mocking'),
+    const child = spawn(
+      process.execPath,
+      [join(__dirname, './fixtures/logging.mjs')],
+      {
+        env: {
+          NODE_DEBUG: 'nock:*',
+        },
+      },
     )
+    const chunks = []
+    child.stderr.setEncoding('utf8')
+    child.stderr.on('data', chunk => {
+      chunks.push(chunk)
+    })
+    child.stderr.on('end', () => {
+      const lines = extractLines(chunks)
+      try {
+        expect(lines.length).to.be.equal(assertions.length)
+        for (let i = 1; i < lines.length; i++) {
+          expect(lines[i], `${i}: ${lines[i]}`).to.match(assertions[i])
+        }
+      } catch (e) {
+        rejectTest(e)
+        return
+      }
+      resolveTest()
+    })
+    await p
   })
 })
+
+const removeEscapeColorsRE =
+  // eslint-disable-next-line no-control-regex
+  /[\u001b\u009b][[()#;?]*(?:[0-9]{1,4}(?:;[0-9]{0,4})*)?[0-9A-ORZcf-nqry=><]/g
+
+function extractLines(chunks) {
+  return chunks
+    .join('')
+    .split('\n')
+    .map(v => v.replace(removeEscapeColorsRE, ''))
+}