diff --git a/README.md b/README.md index 43f1eaaaf..da15ee9d1 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 4128c0d25..bd0d4fd58 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 a1f20fae3..ea6e976af 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 000000000..080a6f8cb --- /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 9811f0780..d5038a73a 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 d82c2446b..a0a118d7d 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 67ef8b946..da09703b4 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 a0bae8e8a..0d3bd6f40 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 91b3e3ff3..d402d6b4f 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 eb51e80d6..2d29a56d1 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 4651aa79f..69fc6cc51 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 e5d901e63..f56b7c4f0 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 a5fadd596..fd9a2db30 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" }, diff --git a/tests/got/fixtures/logging.mjs b/tests/got/fixtures/logging.mjs new file mode 100644 index 000000000..154db5dbb --- /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 39dfb094f..3a3dac69c 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, '')) +}