feat(debug): improve troubleshooting (#752)

* feat(debug): improve troubleshooting
* fix(logger-plugin): improve log output

Author: chimurai

README.md

@@ -81,6 +81,7 @@ _All_ `http-proxy` [options](https://github.com/nodejitsu/node-http-proxy#option
   - [External WebSocket upgrade](#external-websocket-upgrade)
 - [Intercept and manipulate requests](#intercept-and-manipulate-requests)
 - [Intercept and manipulate responses](#intercept-and-manipulate-responses)
+- [Debugging](#debugging)
 - [Working examples](#working-examples)
 - [Recipes](#recipes)
 - [Compatible servers](#compatible-servers)
@@ -546,6 +547,19 @@ const proxy = createProxyMiddleware({
 
 Check out [interception recipes](https://github.com/chimurai/http-proxy-middleware/blob/master/recipes/response-interceptor.md#readme) for more examples.
 
+## Debugging
+
+Configure the `DEBUG` environment variable enable debug logging.
+
+See [`debug`](https://github.com/debug-js/debug#readme) project for more options.
+
+```shell
+DEBUG=http-proxy-middleware* node server.js
+
+$ http-proxy-middleware proxy created +0ms
+$ http-proxy-middleware proxying request to target: 'http://www.example.org' +359ms
+```
+
 ## Working examples
 
 View and play around with [working examples](https://github.com/chimurai/http-proxy-middleware/tree/master/examples).

examples/browser-sync/index.js

@@ -28,3 +28,6 @@ browserSync.init({
 
 console.log('[DEMO] Server: listening on port 3000');
 console.log('[DEMO] Opening: http://localhost:3000/users');
+
+process.on('SIGINT', () => browserSync.exit());
+process.on('SIGTERM', () => browserSync.exit());

examples/connect/index.js

@@ -21,9 +21,12 @@ const app = connect();
  */
 app.use('/users', jsonPlaceholderProxy);
 
-http.createServer(app).listen(3000);
+const server = http.createServer(app).listen(3000);
 
 console.log('[DEMO] Server: listening on port 3000');
 console.log('[DEMO] Opening: http://localhost:3000/users');
 
 require('open')('http://localhost:3000/users');
+
+process.on('SIGINT', () => server.close());
+process.on('SIGTERM', () => server.close());

examples/express/index.js

@@ -21,9 +21,12 @@ const app = express();
  */
 app.use('/users', jsonPlaceholderProxy);
 
-app.listen(3000);
+const server = app.listen(3000);
 
 console.log('[DEMO] Server: listening on port 3000');
 console.log('[DEMO] Opening: http://localhost:3000/users');
 
 require('open')('http://localhost:3000/users');
+
+process.on('SIGINT', () => server.close());
+process.on('SIGTERM', () => server.close());

examples/response-interceptor/index.js

@@ -47,20 +47,16 @@ const jsonPlaceholderProxy = createProxyMiddleware({
   selfHandleResponse: true, // manually call res.end(); IMPORTANT: res.end() is called internally by responseInterceptor()
   on: {
     proxyRes: responseInterceptor(async (buffer, proxyRes, req, res) => {
-      // log original request and proxied request info
-      const exchange = `[DEBUG] ${req.method} ${req.path} -> ${proxyRes.req.protocol}//${proxyRes.req.host}${proxyRes.req.path} [${proxyRes.statusCode}]`;
-      console.log(exchange);
-
       // log original response
       // console.log(`[DEBUG] original response:\n${buffer.toString('utf8')}`);
 
-      // set response content-type
+      console.log('change response content-type');
       res.setHeader('content-type', 'application/json; charset=utf-8');
 
-      // set response status code
+      console.log('change response status code');
       res.statusCode = 418;
 
-      // return a complete different response
+      console.log('return a complete different response');
       return JSON.stringify(favoriteFoods);
     }),
   },
@@ -74,7 +70,7 @@ const app = express();
  */
 app.use(jsonPlaceholderProxy);
 
-app.listen(3000);
+const server = app.listen(3000);
 
 console.log('[DEMO] Server: listening on port 3000');
 console.log('[DEMO] Open: http://localhost:3000/users');
@@ -83,3 +79,6 @@ console.log('[DEMO] Open: http://localhost:3000/gzip');
 console.log('[DEMO] Open: http://localhost:3000/deflate');
 
 require('open')('http://localhost:3000/users');
+
+process.on('SIGINT', () => server.close());
+process.on('SIGTERM', () => server.close());

src/debug.ts

@@ -1,6 +1,6 @@
 import * as createDebug from 'debug';
 
 /**
- * Debug instance with the given namespace: hpm
+ * Debug instance with the given namespace: http-proxy-middleware
  */
-export const debug = createDebug('hpm');
+export const Debug = createDebug('http-proxy-middleware');

src/handlers/response-interceptor.ts

@@ -1,5 +1,9 @@
 import type * as http from 'http';
 import * as zlib from 'zlib';
+import { Debug } from '../debug';
+import { getFunctionName } from '../utils/function';
+
+const debug = Debug.extend('response-interceptor');
 
 type Interceptor = (
   buffer: Buffer,
@@ -16,11 +20,12 @@ type Interceptor = (
  * NOTE: must set options.selfHandleResponse=true (prevent automatic call of res.end())
  */
 export function responseInterceptor(interceptor: Interceptor) {
-  return async function proxyRes(
+  return async function proxyResResponseInterceptor(
     proxyRes: http.IncomingMessage,
     req: http.IncomingMessage,
     res: http.ServerResponse
   ): Promise<void> {
+    debug('intercept proxy response');
     const originalProxyRes = proxyRes;
     let buffer = Buffer.from('', 'utf8');
 
@@ -35,11 +40,14 @@ export function responseInterceptor(interceptor: Interceptor) {
       copyHeaders(proxyRes, res);
 
       // call interceptor with intercepted response (buffer)
+      debug('call interceptor function: %s', getFunctionName(interceptor));
       const interceptedBuffer = Buffer.from(await interceptor(buffer, originalProxyRes, req, res));
 
       // set correct content-length (with double byte character support)
+      debug('set content-length: %s', Buffer.byteLength(interceptedBuffer, 'utf8'));
       res.setHeader('content-length', Buffer.byteLength(interceptedBuffer, 'utf8'));
 
+      debug('write intercepted response');
       res.write(interceptedBuffer);
       res.end();
     });
@@ -73,6 +81,7 @@ function decompress(proxyRes: http.IncomingMessage, contentEncoding: string) {
   }
 
   if (decompress) {
+    debug(`decompress proxy response with 'content-encoding': %s`, contentEncoding);
     _proxyRes.pipe(decompress);
     _proxyRes = decompress;
   }
@@ -85,6 +94,8 @@ function decompress(proxyRes: http.IncomingMessage, contentEncoding: string) {
  * https://github.com/apache/superset/blob/9773aba522e957ed9423045ca153219638a85d2f/superset-frontend/webpack.proxy-config.js#L78
  */
 function copyHeaders(originalResponse, response) {
+  debug('copy original response headers');
+
   response.statusCode = originalResponse.statusCode;
   response.statusMessage = originalResponse.statusMessage;
 

src/http-proxy-middleware.ts

@@ -1,15 +1,15 @@
 import type * as https from 'https';
-import type { Request, RequestHandler, Options, Filter, Logger } from './types';
+import type { Request, RequestHandler, Options, Filter } from './types';
 import * as httpProxy from 'http-proxy';
 import { verifyConfig } from './configuration';
 import { getPlugins } from './get-plugins';
 import { matchPathFilter } from './path-filter';
-import { getLogger } from './logger';
 import * as PathRewriter from './path-rewriter';
 import * as Router from './router';
+import { Debug as debug } from './debug';
+import { getFunctionName } from './utils/function';
 
 export class HttpProxyMiddleware {
-  private logger: Logger;
   private wsInternalSubscribed = false;
   private serverOnCloseSubscribed = false;
   private proxyOptions: Options;
@@ -18,12 +18,10 @@ export class HttpProxyMiddleware {
 
   constructor(options: Options) {
     verifyConfig(options);
-    this.logger = getLogger(options);
     this.proxyOptions = options;
 
-    // create proxy
+    debug(`create proxy server`);
     this.proxy = httpProxy.createProxyServer({});
-    this.logger.info(`[HPM] Proxy created: %O`, options.target);
 
     this.registerPlugins(this.proxy, this.proxyOptions);
 
@@ -43,6 +41,7 @@ export class HttpProxyMiddleware {
     if (this.shouldProxy(this.proxyOptions.pathFilter, req)) {
       try {
         const activeProxyOptions = await this.prepareProxyRequest(req);
+        debug(`proxy request to target: %O`, activeProxyOptions.target);
         this.proxy.web(req, res, activeProxyOptions);
       } catch (err) {
         next && next(err);
@@ -63,7 +62,7 @@ export class HttpProxyMiddleware {
 
     if (server && !this.serverOnCloseSubscribed) {
       server.on('close', () => {
-        this.logger.info('[HPM] server close signal received: closing proxy server');
+        debug('server close signal received: closing proxy server');
         this.proxy.close();
       });
       this.serverOnCloseSubscribed = true;
@@ -77,11 +76,15 @@ export class HttpProxyMiddleware {
 
   private registerPlugins(proxy: httpProxy, options: Options) {
     const plugins = getPlugins(options);
-    plugins.forEach((plugin) => plugin(proxy, options));
+    plugins.forEach((plugin) => {
+      debug(`register plugin: "${getFunctionName(plugin)}"`);
+      plugin(proxy, options);
+    });
   }
 
   private catchUpgradeRequest = (server: https.Server) => {
     if (!this.wsInternalSubscribed) {
+      debug('subscribing to server upgrade event');
       server.on('upgrade', this.handleUpgrade);
       // prevent duplicate upgrade handling;
       // in case external upgrade is also configured
@@ -93,7 +96,7 @@ export class HttpProxyMiddleware {
     if (this.shouldProxy(this.proxyOptions.pathFilter, req)) {
       const activeProxyOptions = await this.prepareProxyRequest(req);
       this.proxy.ws(req, socket, head, activeProxyOptions);
-      this.logger.info('[HPM] Upgrading to WebSocket');
+      debug('server upgrade event received. Proxying WebSocket');
     }
   };
 
@@ -132,7 +135,7 @@ export class HttpProxyMiddleware {
       newTarget = await Router.getTarget(req, options);
 
       if (newTarget) {
-        this.logger.info('[HPM] Router new target: %s -> "%s"', options.target, newTarget);
+        debug('router new target: "%s"', newTarget);
         options.target = newTarget;
       }
     }
@@ -144,9 +147,10 @@ export class HttpProxyMiddleware {
       const path = await pathRewriter(req.url, req);
 
       if (typeof path === 'string') {
+        debug('pathRewrite new path: %s', req.url);
         req.url = path;
       } else {
-        this.logger.info('[HPM] pathRewrite: No rewritten path found. (%s)', req.url);
+        debug('pathRewrite: no rewritten path found: %s', req.url);
       }
     }
   };

src/path-rewriter.ts

@@ -1,8 +1,8 @@
 import isPlainObj = require('is-plain-obj');
 import { ERRORS } from './errors';
-import { debug } from './debug';
+import { Debug } from './debug';
 
-const log = debug.extend('path-rewriter');
+const debug = Debug.extend('path-rewriter');
 
 /**
  * Create rewrite function, to cache parsed rewrite rules.
@@ -31,7 +31,7 @@ export function createPathRewriter(rewriteConfig) {
     for (const rule of rulesCache) {
       if (rule.regex.test(path)) {
         result = result.replace(rule.regex, rule.value);
-        log('rewriting path from "%s" to "%s"', path, result);
+        debug('rewriting path from "%s" to "%s"', path, result);
         break;
       }
     }
@@ -56,12 +56,12 @@ function parsePathRewriteRules(rewriteConfig) {
   const rules = [];
 
   if (isPlainObj(rewriteConfig)) {
-    for (const [key] of Object.entries(rewriteConfig)) {
+    for (const [key, value] of Object.entries(rewriteConfig)) {
       rules.push({
         regex: new RegExp(key),
-        value: rewriteConfig[key],
+        value: value,
       });
-      log('rewrite rule created: "%s" ~> "%s"', key, rewriteConfig[key]);
+      debug('rewrite rule created: "%s" ~> "%s"', key, value);
     }
   }
 

src/plugins/default/debug-proxy-errors-plugin.ts

@@ -1,7 +1,7 @@
-import { debug } from '../../debug';
+import { Debug } from '../../debug';
 import { Plugin } from '../../types';
 
-const debugError = debug.extend('debug-proxy-errors-plugin');
+const debug = Debug.extend('debug-proxy-errors-plugin');
 
 /**
  * Subscribe to {@link https://www.npmjs.com/package/http-proxy#listening-for-proxy-events http-proxy error events} to prevent server from crashing.
@@ -13,12 +13,12 @@ export const debugProxyErrorsPlugin: Plugin = (proxyServer): void => {
    * Prevent server from crashing when http-proxy errors (uncaught errors)
    */
   proxyServer.on('error', (error, req, res, target) => {
-    debugError(`http-proxy error event: \n%O`, error);
+    debug(`http-proxy error event: \n%O`, error);
   });
 
   proxyServer.on('proxyReq', (proxyReq, req, socket) => {
     socket.on('error', (error) => {
-      debugError('Socket error in proxyReq event: \n%O', error);
+      debug('Socket error in proxyReq event: \n%O', error);
     });
   });
 
@@ -30,7 +30,7 @@ export const debugProxyErrorsPlugin: Plugin = (proxyServer): void => {
   proxyServer.on('proxyRes', (proxyRes, req, res) => {
     res.on('close', () => {
       if (!res.writableEnded) {
-        debugError('Destroying proxyRes in proxyRes close event');
+        debug('Destroying proxyRes in proxyRes close event');
         proxyRes.destroy();
       }
     });
@@ -43,23 +43,23 @@ export const debugProxyErrorsPlugin: Plugin = (proxyServer): void => {
    */
   proxyServer.on('proxyReqWs', (proxyReq, req, socket) => {
     socket.on('error', (error) => {
-      debugError('Socket error in proxyReqWs event: \n%O', error);
+      debug('Socket error in proxyReqWs event: \n%O', error);
     });
   });
 
   proxyServer.on('open', (proxySocket) => {
     proxySocket.on('error', (error) => {
-      debugError('Socket error in open event: \n%O', error);
+      debug('Socket error in open event: \n%O', error);
     });
   });
 
   proxyServer.on('close', (req, socket, head) => {
     socket.on('error', (error) => {
-      debugError('Socket error in close event: \n%O', error);
+      debug('Socket error in close event: \n%O', error);
     });
   });
 
   proxyServer.on('econnreset', (error, req, res, target) => {
-    debugError(`http-proxy econnreset event: \n%O`, error);
+    debug(`http-proxy econnreset event: \n%O`, error);
   });
 };

src/plugins/default/logger-plugin.ts

@@ -23,14 +23,23 @@ export const loggerPlugin: Plugin = (proxyServer, options) => {
    * ```
    */
   proxyServer.on('proxyRes', (proxyRes: any, req: any, res) => {
-    const exchange = `[HPM] ${req.method} ${req.baseUrl}${req.path} -> ${proxyRes.req.protocol}//${proxyRes.req.host}${proxyRes.req.path} [${proxyRes.statusCode}]`;
+    // BrowserSync uses req.originalUrl
+    const originalUrl = req.originalUrl ?? `${req.baseUrl}${req.path}`;
+    const exchange = `[HPM] ${req.method} ${originalUrl} -> ${proxyRes.req.protocol}//${proxyRes.req.host}${proxyRes.req.path} [${proxyRes.statusCode}]`;
     logger.info(exchange);
   });
 
+  /**
+   * When client opens WebSocket connection
+   */
+  proxyServer.on('open', (socket) => {
+    logger.info('[HPM] Client connected: %o', socket.address());
+  });
+
   /**
    * When client closes WebSocket connection
    */
   proxyServer.on('close', (req, proxySocket, proxyHead) => {
-    logger.info('[HPM] Client disconnected');
+    logger.info('[HPM] Client disconnected: %o', proxySocket.address());
   });
 };