Merge pull request #503 from wheresrhys/debug-logs-1

Debug logs 1

README.md

@@ -2,7 +2,7 @@
 
 Mock http requests made using [fetch](https://developer.mozilla.org/en-US/docs/Web/API/WindowOrWorkerGlobalScope/fetch).
 
-*New* If using jest, try the new [fetch-mock-jest](https://www.npmjs.com/package/fetch-mock-jest) wrapper.
+_New_ If using jest, try the new [fetch-mock-jest](https://www.npmjs.com/package/fetch-mock-jest) wrapper.
 
 ![node version](https://img.shields.io/node/v/fetch-mock.svg?style=flat-square)
 [![licence](https://img.shields.io/npm/l/fetch-mock.svg?style=flat-square)](https://github.com/wheresrhys/fetch-mock/blob/master/LICENSE)

docs/_troubleshooting/troubleshooting.md

@@ -2,6 +2,8 @@
 title: General
 position: 1
 content_markdown: |-
+  The first  step when debugging tests should be to run with the environment variable `DEBUG=fetch-mock*`. This will output additional logs for debugging purposes.
+
   ### `fetch` is assigned to a local variable, not a global
 
   First of all, consider whether you could just use `fetch` as a global. Here are 3 reasons why this is a good idea:

docs/_usage/debug-mode.md

@@ -0,0 +1,6 @@
+---
+title: Debugging
+position: 8
+content_markdown: |-
+  The first  step when debugging tests should be to run with the environment variable `DEBUG=fetch-mock*`. This will output additional logs for debugging purposes.
+---

package.json

@@ -55,6 +55,7 @@
   "dependencies": {
     "babel-runtime": "^6.26.0",
     "core-js": "^3.0.0",
+    "debug": "^4.1.1",
     "glob-to-regexp": "^0.4.0",
     "lodash.isequal": "^4.5.0",
     "path-to-regexp": "^2.2.1",

src/lib/compile-route.js

@@ -1,3 +1,4 @@
+const { getDebug } = require('./debug');
 const generateMatcher = require('./generate-matcher');
 
 const matcherProperties = [
@@ -14,6 +15,7 @@ const isUrlMatcher = matcher =>
 	matcher instanceof RegExp ||
 	typeof matcher === 'string' ||
 	(typeof matcher === 'object' && 'href' in matcher);
+
 const isFunctionMatcher = matcher => typeof matcher === 'function';
 
 const argsToRoute = args => {
@@ -36,19 +38,28 @@ const argsToRoute = args => {
 };
 
 const sanitizeRoute = route => {
+	const debug = getDebug('sanitizeRoute()');
+	debug('Sanitizing route properties');
 	route = Object.assign({}, route);
 
 	if (route.method) {
+		debug(`Converting method ${route.method} to lower case`);
 		route.method = route.method.toLowerCase();
 	}
 	if (isUrlMatcher(route.matcher)) {
+		debug('Mock uses a url matcher', route.matcher);
 		route.url = route.matcher;
 		delete route.matcher;
 	}
 
 	route.functionMatcher = route.matcher || route.functionMatcher;
 
+	debug('Setting route.identifier...');
+	debug(`  route.name is ${route.name}`);
+	debug(`  route.url is ${route.url}`);
+	debug(`  route.functionMatcher is ${route.functionMatcher}`);
 	route.identifier = route.name || route.url || route.functionMatcher;
+	debug(`  -> route.identifier set to ${route.identifier}`);
 	return route;
 };
 
@@ -64,11 +75,17 @@ const validateRoute = route => {
 	}
 };
 
-const limitMatcher = route => {
+const limit = route => {
+	const debug = getDebug('limit()');
+	debug('Limiting number of requests to handle by route');
 	if (!route.repeat) {
+		debug(
+			'  No `repeat` value set on route. Will match any number of requests'
+		);
 		return;
 	}
 
+	debug(`  Route set to repeat ${route.repeat} times`);
 	const matcher = route.matcher;
 	let timesLeft = route.repeat;
 	route.matcher = (url, options) => {
@@ -82,19 +99,30 @@ const limitMatcher = route => {
 };
 
 const delayResponse = route => {
+	const debug = getDebug('delayResponse()');
+	debug(`Applying response delay settings`);
 	const { delay } = route;
 	if (delay) {
+		debug(`  Wrapping response in delay of ${delay} miliseconds`);
 		const response = route.response;
-		route.response = () =>
-			new Promise(res => setTimeout(() => res(response), delay));
+		route.response = () => {
+			debug(`Delaying response by ${delay} miliseconds`);
+			return new Promise(res => setTimeout(() => res(response), delay));
+		};
+	} else {
+		debug(
+			`  No delay set on route. Will respond 'immediately' (but asynchronously)`
+		);
 	}
 };
 
 const compileRoute = function(args) {
+	const debug = getDebug('compileRoute()');
+	debug('Compiling route');
 	const route = sanitizeRoute(argsToRoute(args));
 	validateRoute(route);
 	route.matcher = generateMatcher(route);
-	limitMatcher(route);
+	limit(route);
 	delayResponse(route);
 	return route;
 };

src/lib/debug.js

@@ -0,0 +1,29 @@
+const debug = require('debug');
+
+let debugFunc;
+let phase = 'default';
+let namespace = '';
+const newDebug = () => {
+	debugFunc = namespace
+		? debug(`fetch-mock:${phase}:${namespace}`)
+		: debug(`fetch-mock:${phase}`);
+};
+
+const newDebugSandbox = ns => debug(`fetch-mock:${phase}:${ns}`);
+
+newDebug();
+
+module.exports = {
+	debug: (...args) => {
+		debugFunc(...args);
+	},
+	setDebugNamespace: str => {
+		namespace = str;
+		newDebug();
+	},
+	setDebugPhase: str => {
+		phase = str || 'default';
+		newDebug();
+	},
+	getDebug: namespace => newDebugSandbox(namespace)
+};

src/lib/fetch-handler.js

@@ -1,3 +1,4 @@
+const { debug, setDebugPhase, getDebug } = require('./debug');
 const responseBuilder = require('./response-builder');
 const requestUtils = require('./request-utils');
 const FetchMock = {};
@@ -23,6 +24,8 @@ const resolve = async (
 	options,
 	request
 ) => {
+	const debug = getDebug('resolve()');
+	debug('Recursively resolving function and promise responses');
 	// We want to allow things like
 	// - function returning a Promise for a response
 	// - delaying (using a timeout Promise) a function's execution to generate
@@ -32,21 +35,36 @@ const resolve = async (
 	// have something that looks like neither Promise nor function
 	while (true) {
 		if (typeof response === 'function') {
+			debug('  Response is a function');
 			// in the case of falling back to the network we need to make sure we're using
 			// the original Request instance, not our normalised url + options
-			response =
-				request && responseIsFetch
-					? response(request)
-					: response(url, options, request);
+			if (responseIsFetch) {
+				if (request) {
+					debug('  -> Calling fetch with Request instance');
+					return response(request);
+				}
+				debug('  -> Calling fetch with url and options');
+				return response(url, options);
+			} else {
+				debug('  -> Calling response function');
+				response = response(url, options, request);
+			}
 		} else if (typeof response.then === 'function') {
+			debug('  Response is a promise');
+			debug('  -> Resolving promise');
 			response = await response;
 		} else {
+			debug('  Response is not a function or a promise');
+			debug('  -> Exiting response resolution recursion');
 			return response;
 		}
 	}
 };
 
 FetchMock.fetchHandler = function(url, options, request) {
+	setDebugPhase('handle');
+	const debug = getDebug('fetchHandler()');
+	debug('fetch called with:', url, options);
 	const normalizedRequest = requestUtils.normalizeRequest(
 		url,
 		options,
@@ -57,6 +75,12 @@ FetchMock.fetchHandler = function(url, options, request) {
 
 	const { signal } = normalizedRequest;
 
+	debug('Request normalised');
+	debug('  url', url);
+	debug('  options', options);
+	debug('  request', request);
+	debug('  signal', signal);
+
 	const route = this.executeRouter(url, options, request);
 
 	// this is used to power the .flush() method
@@ -67,7 +91,9 @@ FetchMock.fetchHandler = function(url, options, request) {
 	// constructors defined by the user
 	return new this.config.Promise((res, rej) => {
 		if (signal) {
+			debug('signal exists - enabling fetch abort');
 			const abort = () => {
+				debug('aborting fetch');
 				// note that DOMException is not available in node.js; even node-fetch uses a custom error class: https://github.com/bitinn/node-fetch/blob/master/src/abort-error.js
 				rej(
 					typeof DOMException !== 'undefined'
@@ -77,27 +103,37 @@ FetchMock.fetchHandler = function(url, options, request) {
 				done();
 			};
 			if (signal.aborted) {
+				debug('signal is already aborted - aborting the fetch');
 				abort();
 			}
 			signal.addEventListener('abort', abort);
 		}
 
 		this.generateResponse(route, url, options, request)
 			.then(res, rej)
-			.then(done, done);
+			.then(done, done)
+			.then(() => {
+				setDebugPhase();
+			});
 	});
 };
 
 FetchMock.fetchHandler.isMock = true;
 
 FetchMock.executeRouter = function(url, options, request) {
+	const debug = getDebug('executeRouter()');
+	debug(`Attempting to match request to a route`);
 	if (this.config.fallbackToNetwork === 'always') {
+		debug(
+			'  Configured with fallbackToNetwork=always - passing through to fetch'
+		);
 		return { response: this.getNativeFetch(), responseIsFetch: true };
 	}
 
 	const match = this.router(url, options, request);
 
 	if (match) {
+		debug('  Matching route found');
 		return match;
 	}
 
@@ -108,6 +144,7 @@ FetchMock.executeRouter = function(url, options, request) {
 	this.push({ url, options, request, isUnmatched: true });
 
 	if (this.fallbackResponse) {
+		debug('  No matching route found - using fallbackResponse');
 		return { response: this.fallbackResponse };
 	}
 
@@ -119,20 +156,24 @@ FetchMock.executeRouter = function(url, options, request) {
 		);
 	}
 
+	debug('  Configured to fallbackToNetwork - passing through to fetch');
 	return { response: this.getNativeFetch(), responseIsFetch: true };
 };
 
 FetchMock.generateResponse = async function(route, url, options, request) {
+	const debug = getDebug('generateResponse()');
 	const response = await resolve(route, url, options, request);
 
 	// If the response says to throw an error, throw it
 	// Type checking is to deal with sinon spies having a throws property :-0
 	if (response.throws && typeof response !== 'function') {
+		debug('response.throws is defined - throwing an error');
 		throw response.throws;
 	}
 
 	// If the response is a pre-made Response, respond with it
 	if (this.config.Response.prototype.isPrototypeOf(response)) {
+		debug('response is already a Response instance - returning it');
 		return response;
 	}
 
@@ -146,7 +187,10 @@ FetchMock.generateResponse = async function(route, url, options, request) {
 };
 
 FetchMock.router = function(url, options, request) {
-	const route = this.routes.find(route => route.matcher(url, options, request));
+	const route = this.routes.find((route, i) => {
+		debug(`Trying to match route ${i}`);
+		return route.matcher(url, options, request);
+	});
 
 	if (route) {
 		this.push({
@@ -163,13 +207,20 @@ FetchMock.getNativeFetch = function() {
 	const func = this.realFetch || (this.isSandbox && this.config.fetch);
 	if (!func) {
 		throw new Error(
-			'fetch-mock: Falling back to network only available on gloabl fetch-mock, or by setting config.fetch on sandboxed fetch-mock'
+			'fetch-mock: Falling back to network only available on global fetch-mock, or by setting config.fetch on sandboxed fetch-mock'
 		);
 	}
 	return func;
 };
 
 FetchMock.push = function({ url, options, request, isUnmatched, identifier }) {
+	debug('Recording fetch call', {
+		url,
+		options,
+		request,
+		isUnmatched,
+		identifier
+	});
 	const args = [url, options];
 	args.request = request;
 	args.identifier = identifier;