From d6f0d1735e4f8104495d9488b208dcc11425733e Mon Sep 17 00:00:00 2001 From: chimurai <655241+chimurai@users.noreply.github.com> Date: Sat, 16 Apr 2022 15:30:13 +0200 Subject: [PATCH] feat(debug): improve troubleshooting (#752) * feat(debug): improve troubleshooting * fix(logger-plugin): improve log output --- README.md | 14 ++++++++++ examples/browser-sync/index.js | 3 +++ examples/connect/index.js | 5 +++- examples/express/index.js | 5 +++- examples/response-interceptor/index.js | 15 +++++------ src/debug.ts | 4 +-- src/handlers/response-interceptor.ts | 13 +++++++++- src/http-proxy-middleware.ts | 26 +++++++++++-------- src/path-rewriter.ts | 12 ++++----- .../default/debug-proxy-errors-plugin.ts | 18 ++++++------- src/plugins/default/logger-plugin.ts | 13 ++++++++-- src/plugins/default/proxy-events.ts | 7 ++--- src/router.ts | 14 +++++----- src/utils/function.ts | 5 ++++ test/e2e/http-proxy-middleware.spec.ts | 6 ++--- test/unit/utils/function.spec.ts | 18 +++++++++++++ 16 files changed, 123 insertions(+), 55 deletions(-) create mode 100644 src/utils/function.ts create mode 100644 test/unit/utils/function.spec.ts diff --git a/README.md b/README.md index bd8faaff..a85bbd71 100644 --- a/README.md +++ b/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). diff --git a/examples/browser-sync/index.js b/examples/browser-sync/index.js index f5171202..879b8b50 100644 --- a/examples/browser-sync/index.js +++ b/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()); diff --git a/examples/connect/index.js b/examples/connect/index.js index 5ab260fb..930097f3 100644 --- a/examples/connect/index.js +++ b/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()); diff --git a/examples/express/index.js b/examples/express/index.js index 7ac72467..bb266f65 100644 --- a/examples/express/index.js +++ b/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()); diff --git a/examples/response-interceptor/index.js b/examples/response-interceptor/index.js index 4ee5a0c0..a39a7b0e 100644 --- a/examples/response-interceptor/index.js +++ b/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()); diff --git a/src/debug.ts b/src/debug.ts index bc985921..0c3f88b6 100644 --- a/src/debug.ts +++ b/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'); diff --git a/src/handlers/response-interceptor.ts b/src/handlers/response-interceptor.ts index cb3c967f..5ddc310f 100644 --- a/src/handlers/response-interceptor.ts +++ b/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 { + 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; diff --git a/src/http-proxy-middleware.ts b/src/http-proxy-middleware.ts index 6454436d..7dad08a4 100644 --- a/src/http-proxy-middleware.ts +++ b/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); } } }; diff --git a/src/path-rewriter.ts b/src/path-rewriter.ts index b56094bd..43782443 100644 --- a/src/path-rewriter.ts +++ b/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); } } diff --git a/src/plugins/default/debug-proxy-errors-plugin.ts b/src/plugins/default/debug-proxy-errors-plugin.ts index 01172b55..59bbb35c 100644 --- a/src/plugins/default/debug-proxy-errors-plugin.ts +++ b/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); }); }; diff --git a/src/plugins/default/logger-plugin.ts b/src/plugins/default/logger-plugin.ts index 6a75db3e..df0b8df5 100644 --- a/src/plugins/default/logger-plugin.ts +++ b/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()); }); }; diff --git a/src/plugins/default/proxy-events.ts b/src/plugins/default/proxy-events.ts index 636e7637..aa686d90 100644 --- a/src/plugins/default/proxy-events.ts +++ b/src/plugins/default/proxy-events.ts @@ -1,7 +1,8 @@ -import { debug } from '../../debug'; +import { Debug } from '../../debug'; import { Plugin } from '../../types'; +import { getFunctionName } from '../../utils/function'; -const log = debug.extend('proxy-events-plugin'); +const debug = Debug.extend('proxy-events-plugin'); /** * Implements option.on object to subscribe to http-proxy events. @@ -25,7 +26,7 @@ const log = debug.extend('proxy-events-plugin'); */ export const proxyEventsPlugin: Plugin = (proxyServer, options) => { Object.entries(options.on || {}).forEach(([eventName, handler]) => { + debug(`register event handler: "${eventName}" -> "${getFunctionName(handler)}"`); proxyServer.on(eventName, handler as (...args: unknown[]) => void); - log(`registered event handler: "${eventName}"`); }); }; diff --git a/src/router.ts b/src/router.ts index 5dcaf659..09e91f29 100644 --- a/src/router.ts +++ b/src/router.ts @@ -1,7 +1,7 @@ import isPlainObj = require('is-plain-obj'); -import { debug } from './debug'; +import { Debug } from './debug'; -const log = debug.extend('router'); +const debug = Debug.extend('router'); export async function getTarget(req, config) { let newTarget; @@ -23,19 +23,19 @@ function getTargetFromProxyTable(req, table) { const hostAndPath = host + path; - for (const [key] of Object.entries(table)) { + for (const [key, value] of Object.entries(table)) { if (containsPath(key)) { if (hostAndPath.indexOf(key) > -1) { // match 'localhost:3000/api' - result = table[key]; - log('router table match: "%s"', key); + result = value; + debug('match: "%s" -> "%s"', key, result); break; } } else { if (key === host) { // match 'localhost:3000' - result = table[key]; - log('router table match: "%s"', host); + result = value; + debug('match: "%s" -> "%s"', host, result); break; } } diff --git a/src/utils/function.ts b/src/utils/function.ts new file mode 100644 index 00000000..cf9c514a --- /dev/null +++ b/src/utils/function.ts @@ -0,0 +1,5 @@ +/* eslint-disable @typescript-eslint/ban-types */ + +export function getFunctionName(fn: Function): string { + return fn.name || '[anonymous Function]'; +} diff --git a/test/e2e/http-proxy-middleware.spec.ts b/test/e2e/http-proxy-middleware.spec.ts index 9b2725eb..3232fd0a 100644 --- a/test/e2e/http-proxy-middleware.spec.ts +++ b/test/e2e/http-proxy-middleware.spec.ts @@ -428,10 +428,8 @@ describe('E2E http-proxy-middleware', () => { await agent.get(`/api/foo/bar`).expect(200); expect(logMessages).not.toBeUndefined(); - expect(logMessages.length).toBe(3); - expect(logMessages[0]).toContain('[HPM] Proxy created:'); - expect(logMessages[1]).toBe('[HPM] GET /api/foo/bar -> http://localhost/api/foo/bar [200]'); - expect(logMessages[2]).toBe('[HPM] server close signal received: closing proxy server'); + expect(logMessages.length).toBe(1); + expect(logMessages[0]).toBe('[HPM] GET /api/foo/bar -> http://localhost/api/foo/bar [200]'); }); }); }); diff --git a/test/unit/utils/function.spec.ts b/test/unit/utils/function.spec.ts new file mode 100644 index 00000000..0c7e1241 --- /dev/null +++ b/test/unit/utils/function.spec.ts @@ -0,0 +1,18 @@ +/* eslint-disable @typescript-eslint/no-empty-function */ +import { getFunctionName } from '../../../src/utils/function'; + +describe('getFunctionName()', () => { + it('should return Function name', () => { + function myFunction() {} + expect(getFunctionName(myFunction)).toBe('myFunction'); + }); + + it('should return arrow Function name', () => { + const myFunction = () => {}; + expect(getFunctionName(myFunction)).toBe('myFunction'); + }); + + it('should return anonymous Function name', () => { + expect(getFunctionName(() => {})).toBe('[anonymous Function]'); + }); +});